logging: move clusterworkspaceshard reconciler to structured logging #1614

stevekuznetsov · 2022-07-25T14:31:35Z

Signed-off-by: Steve Kuznetsov skuznets@redhat.com

Example output:

clusterworkspaceshard_controller.go:99] "Starting controller" reconciler="clusterworkspaceshard"
clusterworkspaceshard_controller.go:88] "queueing workspace shard" reconciler="clusterworkspaceshard" key="root|root"
clusterworkspaceshard_controller.go:125] "processing key" reconciler="clusterworkspaceshard" key="root|root"
clusterworkspaceshard_controller.go:197] "processed ClusterWorkspaceShard" reconciler="clusterworkspaceshard" key="root|root" workspace="root" namespace="" name="root"
clusterworkspaceshard_controller.go:88] "queueing workspace shard" reconciler="clusterworkspaceshard" key="root|root"
clusterworkspaceshard_controller.go:125] "processing key" reconciler="clusterworkspaceshard" key="root|root"
clusterworkspaceshard_controller.go:197] "processed ClusterWorkspaceShard" reconciler="clusterworkspaceshard" key="root|root" workspace="root" namespace="" name="root"
clusterworkspaceshard_controller.go:107] "Shutting down controller" reconciler="clusterworkspaceshard"

/cc @ncdc @sttts

stevekuznetsov · 2022-07-25T15:01:41Z

pkg/reconciler/tenancy/clusterworkspaceshard/clusterworkspaceshard_controller.go

@@ -83,16 +85,19 @@ func (c *Controller) enqueue(obj interface{}) {
 		runtime.HandleError(err)
 		return
 	}
-	klog.Infof("queueing workspace shard %q", key)
+	klog.Background().WithValues(logging.ReconcilerKey, controllerName, logging.KeyKey, key).Info("queueing workspace shard")


Unclear if we ever really need logs here (that we're enqueuing) given that we should be safe to assume that we de-queue at some point.... but in any case there's no context provided to the controller's constructor, so we can't share the logger.

We have had cases where we missed events from the informers. And we had cases with backoffs. Having these has had value.

pkg/logging/constants.go

pkg/reconciler/tenancy/clusterworkspaceshard/clusterworkspaceshard_controller.go

Signed-off-by: Steve Kuznetsov <skuznets@redhat.com>

sttts · 2022-07-25T16:21:39Z

pkg/reconciler/tenancy/clusterworkspaceshard/clusterworkspaceshard_controller.go

@@ -83,16 +85,19 @@ func (c *Controller) enqueue(obj interface{}) {
 		runtime.HandleError(err)
 		return
 	}
-	klog.Infof("queueing workspace shard %q", key)
+	logger := logging.WithQueueKey(logging.WithReconciler(klog.Background(), controllerName), key)


sttts · 2022-07-25T16:34:52Z

pkg/reconciler/tenancy/clusterworkspaceshard/clusterworkspaceshard_controller.go

-	klog.Infof("processing key %q", key)
+	logger := logging.WithQueueKey(klog.FromContext(ctx), key)
+	ctx = klog.NewContext(ctx, logger)
+	logger.Info("processing key")


nit: lower or upper case?

lower probably best?

I tend to prefer lower

sttts · 2022-07-25T16:35:45Z

pkg/reconciler/tenancy/clusterworkspaceshard/clusterworkspaceshard_controller.go

@@ -182,6 +193,7 @@ func (c *Controller) process(ctx context.Context, key string) error {
 		return uerr
 	}

+	logger.V(6).Info("processed ClusterWorkspaceShard")


do these V levels map directly to klog levels?

sttts · 2022-07-25T16:36:30Z

pkg/reconciler/tenancy/clusterworkspaceshard/clusterworkspaceshard_controller.go

 			return nil // object deleted before we handled it
 		}
 		return err
 	}
 	previous := obj
 	obj = obj.DeepCopy()

+	logger = logging.WithObject(logger, obj)
+	ctx = klog.NewContext(ctx, logger)


everytime I see these I wished klog.NewContext would return the logger in order to write

ctx, logger := klog.NewContext(ctx, logging.WithObject(logger, obj))

We'll probably want a helper

Sure, we can do that too - it's not every case where you want to decorate the context and the logger, but can't hurt to over-helper it :)

I would argue that 95% of cases where you forget to augment the context is a mistake.

I think we'll find that 95% of our logging code is in terminal/leaf calls where you're not passing the thing on to anyone else but yes, maybe better just to be explicit about it

for _, item := range collection { logger = logger.WithValue("item", item) // use it }

ncdc · 2022-07-25T19:20:02Z

LGTM. We can always evolve our patterns and styles over time.

Let's also add some logging conventions to a markdown doc somewhere (can be another PR)?

sttts · 2022-07-26T11:25:20Z

/approve
Lgtm.

Anything left open to do?

openshift-ci · 2022-07-26T11:25:28Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: sttts

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:

~~OWNERS~~ [sttts]

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

sttts · 2022-07-27T06:42:03Z

/lgtm

We will iterate.

sttts · 2022-07-27T06:42:17Z

/retest

ncdc · 2022-07-27T13:52:26Z

Hit flake #1626

ncdc · 2022-07-27T13:56:17Z

/retest

stevekuznetsov · 2022-08-05T17:38:19Z

#1694

openshift-ci bot requested review from ncdc and sttts July 25, 2022 14:31

stevekuznetsov force-pushed the skuznets/structured-logging-clusterworkspaceshard-controller branch 2 times, most recently from ac7e356 to 5862781 Compare July 25, 2022 15:00

stevekuznetsov commented Jul 25, 2022

View reviewed changes

stevekuznetsov force-pushed the skuznets/structured-logging-clusterworkspaceshard-controller branch from 5862781 to 8e450e8 Compare July 25, 2022 15:03

sttts reviewed Jul 25, 2022

View reviewed changes

pkg/logging/constants.go Outdated Show resolved Hide resolved

sttts reviewed Jul 25, 2022

View reviewed changes

pkg/logging/constants.go Outdated Show resolved Hide resolved

stevekuznetsov force-pushed the skuznets/structured-logging-clusterworkspaceshard-controller branch from 8e450e8 to d79e1f9 Compare July 25, 2022 15:45

sttts reviewed Jul 25, 2022

View reviewed changes

pkg/reconciler/tenancy/clusterworkspaceshard/clusterworkspaceshard_controller.go Outdated Show resolved Hide resolved

stevekuznetsov force-pushed the skuznets/structured-logging-clusterworkspaceshard-controller branch from d79e1f9 to defdfe0 Compare July 25, 2022 15:48

logging: move clusterworkspaceshard reconciler to structured logging

c3231e0

Signed-off-by: Steve Kuznetsov <skuznets@redhat.com>

stevekuznetsov force-pushed the skuznets/structured-logging-clusterworkspaceshard-controller branch from defdfe0 to c3231e0 Compare July 25, 2022 15:55

sttts reviewed Jul 25, 2022

View reviewed changes

openshift-ci bot added the approved Indicates a PR has been approved by an approver from all required OWNERS files. label Jul 26, 2022

openshift-ci bot assigned sttts Jul 27, 2022

openshift-ci bot added the lgtm Indicates that a PR is ready to be merged. label Jul 27, 2022

openshift-merge-robot merged commit 4a52d62 into kcp-dev:main Jul 27, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

logging: move clusterworkspaceshard reconciler to structured logging #1614

logging: move clusterworkspaceshard reconciler to structured logging #1614

stevekuznetsov commented Jul 25, 2022 •

edited

Loading

stevekuznetsov Jul 25, 2022

sttts Jul 25, 2022

sttts Jul 25, 2022

sttts Jul 25, 2022

stevekuznetsov Jul 25, 2022

sttts Jul 25, 2022

sttts Jul 25, 2022

stevekuznetsov Jul 25, 2022

sttts Jul 25, 2022

ncdc Jul 25, 2022

stevekuznetsov Jul 25, 2022

sttts Jul 25, 2022 •

edited

Loading

stevekuznetsov Jul 25, 2022

stevekuznetsov Jul 25, 2022

ncdc commented Jul 25, 2022

sttts commented Jul 26, 2022

openshift-ci bot commented Jul 26, 2022

sttts commented Jul 27, 2022

sttts commented Jul 27, 2022

ncdc commented Jul 27, 2022

ncdc commented Jul 27, 2022

stevekuznetsov commented Aug 5, 2022

logging: move clusterworkspaceshard reconciler to structured logging #1614

logging: move clusterworkspaceshard reconciler to structured logging #1614

Conversation

stevekuznetsov commented Jul 25, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

sttts Jul 25, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ncdc commented Jul 25, 2022

sttts commented Jul 26, 2022

openshift-ci bot commented Jul 26, 2022

sttts commented Jul 27, 2022

sttts commented Jul 27, 2022

ncdc commented Jul 27, 2022

ncdc commented Jul 27, 2022

stevekuznetsov commented Aug 5, 2022

stevekuznetsov commented Jul 25, 2022 •

edited

Loading

sttts Jul 25, 2022 •

edited

Loading