Skip to content

Commit c774e2f

Browse files
committedDec 5, 2018
Overhaul/unify log tags
This overhauls log tags in CR to ensure that we have consistent style and naming across all of our log lines.
1 parent 8c6043e commit c774e2f

File tree

10 files changed

+118
-35
lines changed

10 files changed

+118
-35
lines changed
 

‎TMP-LOGGING.md

+83
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,83 @@
1+
Logging Guidelines
2+
==================
3+
4+
## Logging errors
5+
6+
Errors should *always* be logged with `log.Error`, which allows logr
7+
implementations to provide special handling of errors (for instance,
8+
providing stack traces in debug mode).
9+
10+
It's acceptible to log call `log.Error` with a nil error object. This
11+
conveys that an error occurred in some capacity, but that no actual
12+
`error` object was involved.
13+
14+
## Logging messages
15+
16+
- Don't put variable content in your messages -- use key-value pairs for
17+
that. Never use `fmt.Sprintf` in your message.
18+
19+
- Try to match the terminology in your messages with your tags -- for
20+
instance, if you have a tag `api version`, use the term `APIVersion`
21+
instead of `GroupVersion` in your message.
22+
23+
## Logging Kubernetes Objects
24+
25+
Kubernetes objects should be logged directly, like `log.Info("this is
26+
a Kubernetes object", "pod", somePod)`. controller-runtime provides
27+
a special encoder for Zap that will transform Kubernetes objects into
28+
`name, namespace, apiVersion, kind` objects, when available and not in
29+
development mode. Other logr implementations should implement similar
30+
logic.
31+
32+
## Logging Tags
33+
34+
- Use lower-case, space separated tags. For example `object` for objects,
35+
`api version` for `APIVersion`
36+
37+
- Be consistent across your application, and with controller-runtime when
38+
possible.
39+
40+
- Try to be brief but descriptive.
41+
42+
- Match terminology in tags with terminology in the message.
43+
44+
- Be careful logging non-Kubernetes objects verbatim if they're very
45+
large.
46+
47+
### Groups, Versions, and Kinds
48+
49+
- Kinds should not be logged alone (they're meanless alone). Use
50+
a `GroupKind` object to log them instead, or a `GroupVersionKind` when
51+
version is relevant.
52+
53+
- If you need to log an API version string, use `api version` as the tag
54+
(formatted as with a `GroupVersion`, or as recieved directly from API
55+
discovery).
56+
57+
### Objects and Types
58+
59+
- If code works with a generic Kubernetes `runtime.Object`, use the
60+
`object` tag. For specific objects, prefer the resource name as the tag
61+
(e.g. `pod` for `v1.Pod` objects).
62+
63+
- For non-Kubernetes objects, the `object` tag may also be used, if you
64+
accept a generic interface.
65+
66+
- When logging a raw type, log it using the `type` tag, with a value of
67+
`fmt.Sprintf("%T", typ)`
68+
69+
- If there's specific context around a type, the tag may be more specific,
70+
but should end with `type` -- for instance, `OwnerType` should be logged
71+
as `owner` in the context of `log.Error(err, "Could not get ObjectKinds
72+
for OwnerType", `owner type`, fmt.Sprintf("%T"))`. When possible, favor
73+
communicating kind instead.
74+
75+
### Multiple things
76+
77+
- When logging multiple things, simply pluralize the tag.
78+
79+
### controller-runtime specifics
80+
81+
- Reconcile requests should be logged as `request`
82+
- Reconcile keys should be logged as with the same tag as if you were
83+
logging the object directly.

‎pkg/client/fake/client.go

+1-1
Original file line numberDiff line numberDiff line change
@@ -59,7 +59,7 @@ func NewFakeClientWithScheme(clientScheme *runtime.Scheme, initObjs ...runtime.O
5959
for _, obj := range initObjs {
6060
err := tracker.Add(obj)
6161
if err != nil {
62-
log.Error(err, "failed to add object", "object", obj)
62+
log.Error(err, "failed to add object to fake client", "object", obj)
6363
os.Exit(1)
6464
return nil
6565
}

‎pkg/handler/enqueue.go

+5-5
Original file line numberDiff line numberDiff line change
@@ -36,7 +36,7 @@ type EnqueueRequestForObject struct{}
3636
// Create implements EventHandler
3737
func (e *EnqueueRequestForObject) Create(evt event.CreateEvent, q workqueue.RateLimitingInterface) {
3838
if evt.Meta == nil {
39-
enqueueLog.Error(nil, "CreateEvent received with no metadata", "CreateEvent", evt)
39+
enqueueLog.Error(nil, "CreateEvent received with no metadata", "event", evt)
4040
return
4141
}
4242
q.Add(reconcile.Request{NamespacedName: types.NamespacedName{
@@ -53,7 +53,7 @@ func (e *EnqueueRequestForObject) Update(evt event.UpdateEvent, q workqueue.Rate
5353
Namespace: evt.MetaOld.GetNamespace(),
5454
}})
5555
} else {
56-
enqueueLog.Error(nil, "UpdateEvent received with no old metadata", "UpdateEvent", evt)
56+
enqueueLog.Error(nil, "UpdateEvent received with no old metadata", "event", evt)
5757
}
5858

5959
if evt.MetaNew != nil {
@@ -62,14 +62,14 @@ func (e *EnqueueRequestForObject) Update(evt event.UpdateEvent, q workqueue.Rate
6262
Namespace: evt.MetaNew.GetNamespace(),
6363
}})
6464
} else {
65-
enqueueLog.Error(nil, "UpdateEvent received with no new metadata", "UpdateEvent", evt)
65+
enqueueLog.Error(nil, "UpdateEvent received with no new metadata", "event", evt)
6666
}
6767
}
6868

6969
// Delete implements EventHandler
7070
func (e *EnqueueRequestForObject) Delete(evt event.DeleteEvent, q workqueue.RateLimitingInterface) {
7171
if evt.Meta == nil {
72-
enqueueLog.Error(nil, "DeleteEvent received with no metadata", "DeleteEvent", evt)
72+
enqueueLog.Error(nil, "DeleteEvent received with no metadata", "event", evt)
7373
return
7474
}
7575
q.Add(reconcile.Request{NamespacedName: types.NamespacedName{
@@ -81,7 +81,7 @@ func (e *EnqueueRequestForObject) Delete(evt event.DeleteEvent, q workqueue.Rate
8181
// Generic implements EventHandler
8282
func (e *EnqueueRequestForObject) Generic(evt event.GenericEvent, q workqueue.RateLimitingInterface) {
8383
if evt.Meta == nil {
84-
enqueueLog.Error(nil, "GenericEvent received with no metadata", "GenericEvent", evt)
84+
enqueueLog.Error(nil, "GenericEvent received with no metadata", "event", evt)
8585
return
8686
}
8787
q.Add(reconcile.Request{NamespacedName: types.NamespacedName{

‎pkg/handler/enqueue_owner.go

+4-4
Original file line numberDiff line numberDiff line change
@@ -90,13 +90,13 @@ func (e *EnqueueRequestForOwner) parseOwnerTypeGroupKind(scheme *runtime.Scheme)
9090
// Get the kinds of the type
9191
kinds, _, err := scheme.ObjectKinds(e.OwnerType)
9292
if err != nil {
93-
log.Error(err, "Could not get ObjectKinds for OwnerType", "OwnerType", e.OwnerType)
93+
log.Error(err, "Could not get ObjectKinds for OwnerType", "owner type", fmt.Sprintf("%T", e.OwnerType))
9494
return err
9595
}
9696
// Expect only 1 kind. If there is more than one kind this is probably an edge case such as ListOptions.
9797
if len(kinds) != 1 {
9898
err := fmt.Errorf("Expected exactly 1 kind for OwnerType %T, but found %s kinds", e.OwnerType, kinds)
99-
log.Error(err, "", "OwnerType", e.OwnerType, "Kinds", kinds)
99+
log.Error(nil, "Expected exactly 1 kind for OwnerType", "owner type", fmt.Sprintf("%T", e.OwnerType), "kinds", kinds)
100100
return err
101101

102102
}
@@ -115,8 +115,8 @@ func (e *EnqueueRequestForOwner) getOwnerReconcileRequest(object metav1.Object)
115115
// Parse the Group out of the OwnerReference to compare it to what was parsed out of the requested OwnerType
116116
refGV, err := schema.ParseGroupVersion(ref.APIVersion)
117117
if err != nil {
118-
log.Error(err, "Could not parse OwnerReference GroupVersion",
119-
"OwnerReference", ref.APIVersion)
118+
log.Error(err, "Could not parse OwnerReference APIVersion",
119+
"api version", ref.APIVersion)
120120
return nil
121121
}
122122

‎pkg/internal/admission/http.go

+1-1
Original file line numberDiff line numberDiff line change
@@ -42,7 +42,7 @@ func (h httpHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
4242
// verify the content type is accurate
4343
contentType := r.Header.Get("Content-Type")
4444
if contentType != "application/json" {
45-
log.Error(nil, "invalid content type, expected application/json", "context type", contentType)
45+
log.Error(nil, "invalid content type, expected application/json", "content type", contentType)
4646
return
4747
}
4848

‎pkg/internal/controller/controller.go

+8-8
Original file line numberDiff line numberDiff line change
@@ -118,7 +118,7 @@ func (c *Controller) Watch(src source.Source, evthdler handler.EventHandler, prc
118118
}
119119
}
120120

121-
log.Info("Starting EventSource", "Controller", c.Name, "Source", src)
121+
log.Info("Starting EventSource", "controller", c.Name, "source", src)
122122
return src.Start(evthdler, c.Queue, prct...)
123123
}
124124

@@ -131,7 +131,7 @@ func (c *Controller) Start(stop <-chan struct{}) error {
131131
defer c.Queue.ShutDown()
132132

133133
// Start the SharedIndexInformer factories to begin populating the SharedIndexInformer caches
134-
log.Info("Starting Controller", "Controller", c.Name)
134+
log.Info("Starting Controller", "controller", c.Name)
135135

136136
// Wait for the caches to be synced before starting workers
137137
if c.WaitForCacheSync == nil {
@@ -141,7 +141,7 @@ func (c *Controller) Start(stop <-chan struct{}) error {
141141
// This code is unreachable right now since WaitForCacheSync will never return an error
142142
// Leaving it here because that could happen in the future
143143
err := fmt.Errorf("failed to wait for %s caches to sync", c.Name)
144-
log.Error(err, "Could not wait for Cache to sync", "Controller", c.Name)
144+
log.Error(err, "Could not wait for Cache to sync", "controller", c.Name)
145145
c.mu.Unlock()
146146
return err
147147
}
@@ -151,7 +151,7 @@ func (c *Controller) Start(stop <-chan struct{}) error {
151151
}
152152

153153
// Launch workers to process resources
154-
log.Info("Starting workers", "Controller", c.Name, "WorkerCount", c.MaxConcurrentReconciles)
154+
log.Info("Starting workers", "controller", c.Name, "worker count", c.MaxConcurrentReconciles)
155155
for i := 0; i < c.MaxConcurrentReconciles; i++ {
156156
// Process work items
157157
go wait.Until(func() {
@@ -164,7 +164,7 @@ func (c *Controller) Start(stop <-chan struct{}) error {
164164
c.mu.Unlock()
165165

166166
<-stop
167-
log.Info("Stopping workers", "Controller", c.Name)
167+
log.Info("Stopping workers", "controller", c.Name)
168168
return nil
169169
}
170170

@@ -203,7 +203,7 @@ func (c *Controller) processNextWorkItem() bool {
203203
// process a work item that is invalid.
204204
c.Queue.Forget(obj)
205205
log.Error(nil, "Queue item was not a Request",
206-
"Controller", c.Name, "Type", fmt.Sprintf("%T", obj), "Value", obj)
206+
"controller", c.Name, "type", fmt.Sprintf("%T", obj), "value", obj)
207207
// Return true, don't take a break
208208
return true
209209
}
@@ -212,7 +212,7 @@ func (c *Controller) processNextWorkItem() bool {
212212
// resource to be synced.
213213
if result, err := c.Do.Reconcile(req); err != nil {
214214
c.Queue.AddRateLimited(req)
215-
log.Error(err, "Reconciler error", "Controller", c.Name, "Request", req)
215+
log.Error(err, "Reconciler error", "controller", c.Name, "request", req)
216216
ctrlmetrics.ReconcileErrors.WithLabelValues(c.Name).Inc()
217217

218218
return false
@@ -229,7 +229,7 @@ func (c *Controller) processNextWorkItem() bool {
229229
c.Queue.Forget(obj)
230230

231231
// TODO(directxman12): What does 1 mean? Do we want level constants? Do we want levels at all?
232-
log.V(1).Info("Successfully Reconciled", "Controller", c.Name, "Request", req)
232+
log.V(1).Info("Successfully Reconciled", "controller", c.Name, "request", req)
233233

234234
// Return true, don't take a break
235235
return true

‎pkg/predicate/predicate.go

+4-4
Original file line numberDiff line numberDiff line change
@@ -96,19 +96,19 @@ type ResourceVersionChangedPredicate struct {
9696
// Update implements default UpdateEvent filter for validating resource version change
9797
func (ResourceVersionChangedPredicate) Update(e event.UpdateEvent) bool {
9898
if e.MetaOld == nil {
99-
log.Error(nil, "UpdateEvent has no old metadata", "UpdateEvent", e)
99+
log.Error(nil, "UpdateEvent has no old metadata", "event", e)
100100
return false
101101
}
102102
if e.ObjectOld == nil {
103-
log.Error(nil, "GenericEvent has no old runtime object to update", "GenericEvent", e)
103+
log.Error(nil, "GenericEvent has no old runtime object to update", "event", e)
104104
return false
105105
}
106106
if e.ObjectNew == nil {
107-
log.Error(nil, "GenericEvent has no new runtime object for update", "GenericEvent", e)
107+
log.Error(nil, "GenericEvent has no new runtime object for update", "event", e)
108108
return false
109109
}
110110
if e.MetaNew == nil {
111-
log.Error(nil, "UpdateEvent has no new metadata", "UpdateEvent", e)
111+
log.Error(nil, "UpdateEvent has no new metadata", "event", e)
112112
return false
113113
}
114114
if e.MetaNew.GetResourceVersion() == e.MetaOld.GetResourceVersion() {

‎pkg/source/internal/eventsource.go

+10-10
Original file line numberDiff line numberDiff line change
@@ -51,7 +51,7 @@ func (e EventHandler) OnAdd(obj interface{}) {
5151
c.Meta = o
5252
} else {
5353
log.Error(err, "OnAdd missing Meta",
54-
"Object", obj, "Type", fmt.Sprintf("%T", obj))
54+
"object", obj, "type", fmt.Sprintf("%T", obj))
5555
return
5656
}
5757

@@ -60,7 +60,7 @@ func (e EventHandler) OnAdd(obj interface{}) {
6060
c.Object = o
6161
} else {
6262
log.Error(nil, "OnAdd missing runtime.Object",
63-
"Object", obj, "Type", fmt.Sprintf("%T", obj))
63+
"object", obj, "type", fmt.Sprintf("%T", obj))
6464
return
6565
}
6666

@@ -83,7 +83,7 @@ func (e EventHandler) OnUpdate(oldObj, newObj interface{}) {
8383
u.MetaOld = o
8484
} else {
8585
log.Error(err, "OnUpdate missing MetaOld",
86-
"Object", oldObj, "Type", fmt.Sprintf("%T", oldObj))
86+
"object", oldObj, "type", fmt.Sprintf("%T", oldObj))
8787
return
8888
}
8989

@@ -92,7 +92,7 @@ func (e EventHandler) OnUpdate(oldObj, newObj interface{}) {
9292
u.ObjectOld = o
9393
} else {
9494
log.Error(nil, "OnUpdate missing ObjectOld",
95-
"Object", oldObj, "Type", fmt.Sprintf("%T", oldObj))
95+
"object", oldObj, "type", fmt.Sprintf("%T", oldObj))
9696
return
9797
}
9898

@@ -101,7 +101,7 @@ func (e EventHandler) OnUpdate(oldObj, newObj interface{}) {
101101
u.MetaNew = o
102102
} else {
103103
log.Error(err, "OnUpdate missing MetaNew",
104-
"Object", newObj, "Type", fmt.Sprintf("%T", newObj))
104+
"object", newObj, "type", fmt.Sprintf("%T", newObj))
105105
return
106106
}
107107

@@ -110,7 +110,7 @@ func (e EventHandler) OnUpdate(oldObj, newObj interface{}) {
110110
u.ObjectNew = o
111111
} else {
112112
log.Error(nil, "OnUpdate missing ObjectNew",
113-
"Object", oldObj, "Type", fmt.Sprintf("%T", oldObj))
113+
"object", oldObj, "type", fmt.Sprintf("%T", oldObj))
114114
return
115115
}
116116

@@ -139,8 +139,8 @@ func (e EventHandler) OnDelete(obj interface{}) {
139139
tombstone, ok := obj.(cache.DeletedFinalStateUnknown)
140140
if !ok {
141141
log.Error(nil, "Error decoding objects. Expected cache.DeletedFinalStateUnknown",
142-
"Type", fmt.Sprintf("%T", obj),
143-
"Object", obj)
142+
"type", fmt.Sprintf("%T", obj),
143+
"object", obj)
144144
return
145145
}
146146

@@ -153,7 +153,7 @@ func (e EventHandler) OnDelete(obj interface{}) {
153153
d.Meta = o
154154
} else {
155155
log.Error(err, "OnDelete missing Meta",
156-
"Object", obj, "Type", fmt.Sprintf("%T", obj))
156+
"object", obj, "type", fmt.Sprintf("%T", obj))
157157
return
158158
}
159159

@@ -162,7 +162,7 @@ func (e EventHandler) OnDelete(obj interface{}) {
162162
d.Object = o
163163
} else {
164164
log.Error(nil, "OnDelete missing runtime.Object",
165-
"Object", obj, "Type", fmt.Sprintf("%T", obj))
165+
"object", obj, "type", fmt.Sprintf("%T", obj))
166166
return
167167
}
168168

‎pkg/webhook/admission/http.go

+1-1
Original file line numberDiff line numberDiff line change
@@ -70,7 +70,7 @@ func (wh *Webhook) ServeHTTP(w http.ResponseWriter, r *http.Request) {
7070
contentType := r.Header.Get("Content-Type")
7171
if contentType != "application/json" {
7272
err = fmt.Errorf("contentType=%s, expect application/json", contentType)
73-
log.Error(err, "unable to process a request with an unknown content type")
73+
log.Error(err, "unable to process a request with an unknown content type", "content type", contentType)
7474
reviewResponse = ErrorResponse(http.StatusBadRequest, err)
7575
writeResponse(w, reviewResponse)
7676
return

‎pkg/webhook/internal/cert/writer/fs.go

+1-1
Original file line numberDiff line numberDiff line change
@@ -114,7 +114,7 @@ func prepareToWrite(dir string) error {
114114
_, err := os.Stat(dir)
115115
switch {
116116
case os.IsNotExist(err):
117-
log.Info(fmt.Sprintf("cert directory %v doesn't exist, creating", dir))
117+
log.Info("cert directory doesn't exist, creating", "directory", dir)
118118
// TODO: figure out if we can reduce the permission. (Now it's 0777)
119119
err = os.MkdirAll(dir, 0777)
120120
if err != nil {

0 commit comments

Comments
 (0)