switch to structured logging #258

pinikomarov · 2023-09-02T22:38:44Z

This automatically adds additional fields like reconcile_id etc.. from the controller context.

before :

2023-05-18T01:53:14+03:00 INFO controllers.KeystoneAPI Reconciled Service init successfully

after:

2023-10-04T16:06:31+03:00 INFO Controllers.CinderAPI Reconciled Service 'cinder-api' successfully {"controller": "cinderapi", "controllerGroup": "cinder.openstack.org", "controllerKind": "CinderAPI", "CinderAPI": {"name":"cinder-api","namespace":"openstack"}, "namespace": "openstack", "name": "cinder-api", "reconcileID": "09fed477-8ad5-4186-8b20-790f409de78a"}

*by using per reconcile function respective logger objects, the intention is to lay the ground for parallel reconciliation in future and avoid race conditions as ctx objects are reconcile run specific.

openshift-ci · 2023-09-02T22:38:56Z

Hi @pinikomarov. Thanks for your PR.

I'm waiting for a openstack-k8s-operators member to verify that this patch is reasonable to test. If it is, they should reply with /ok-to-test on its own line. Until that is done, I will not automatically test new commits in this PR, but the usual testing commands by org members will still work. Regular contributors should join the org to skip this step.

Once the patch is verified, the new status will be reflected by the ok-to-test label.

I understand the commands that are listed here.

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

Akrog · 2023-09-05T09:55:11Z

controllers/cinderscheduler_controller.go

@@ -87,7 +79,7 @@ type CinderSchedulerReconciler struct {

 // Reconcile -
 func (r *CinderSchedulerReconciler) Reconcile(ctx context.Context, req ctrl.Request) (result ctrl.Result, _err error) {
-	_ = log.FromContext(ctx)
+	log := GetLog(ctx, "CinderBackup")


-1: All calls in this file should be using CinderScheduler or CinderSch whatever we prefer.

right , correcting

ASBishop · 2023-09-20T16:16:22Z

controllers/cinder_controller.go

@@ -223,6 +222,9 @@ func (r *CinderReconciler) SetupWithManager(mgr ctrl.Manager) error {
 	// matches the name of an existing Cinder CR.  In that case changes to that secret would trigger
 	// reconciliation for a Cinder CR that does not need it.
 	//
+
+	log := GetLog(ctx, "Cinder")


Is there any way to persist this, similar to how the previous code used r.log? My concern is that every function that wants to log something will need to repeat L226 in order to obtain its own 'log' object.

I'm experimenting with an alternative approach, and might submit my own PR just as a PoC.

Hi Alan, we're trying the drop the use of the global logger in the struct,
We discussed it here :
It's to do with parallel reconcile use case and making room for differentiating each reconcile_id if that happens.
openstack-k8s-operators/keystone-operator#220 (comment)

Also the Gibbi believes that the pattern of of using the r.log from the global struct
to pass request specific info between different reconcile calls is not a good pattern.
Gibbi commented on the r.log usage here :
openstack-k8s-operators/nova-operator#496 (comment)

@gibizer fyi ^^

about placing the getLog.. func in the funcs module - cinder.GetLoggerWithContex , as in your patch ,I'm good with that either way

Yepp. The Reconciler struct survives between Reconcile calls. Also it is shared between any parallel Reconcile calls. (At the moment I think we are not configured with parallel reconciliation but we can, and we might need that in the future to speed things up). In general we should not store any reconcile request specific data in the Reconciler struct due to this reason. The framework sets up the logger in the context with reconcile request specific data, like the uid of the resource to be reconciled.

Thanks, this helps me understand why my alternate approach (sharing the Reconciler struct) isn't the right way to go. My hope was (and still is) there's a way for every function that wants to log something to not have to call GetLogger(). The main thing I'd like to avoid is the caller having to provide the controller name ("Cinder" vs "CinderAPI"). That would reduce the chance of a copy/paste error, where a function for controller X generates a log that looks like it came from controller Y (Gorka pointed out one such instance in this PR). Perhaps each controller could provide a local wrapper function, so the controller name is specified only once?

As I see it we have to options here :

// Option 1:

// Per controller wrapper function that wraps the GetLog
func getLogWrapper(ctx context.Context) func(context.Context, string) logr.Logger{
return GetLog(ctx, "Heat")
}

//usage
func (...) Reconcile...
log := getLogWrapper(ctx)

// OR

// Option 2 ,at the head of each controller_.go we have a non exported local func with a statically named controller:
func getLog(ctx context.Context) logr.Logger {
return log.FromContext(ctx).WithName("Controllers").WithName("Heat")
}

//usage
func (...) Reconcile...
log := getLog(ctx)

// Either way I think about implementation, the simplest use case to seems to me is option 2.

WDYT ?

Option 2 looks good to me

I also prefer option 2.

Another issue following that is that the getlog func signitures need to be unique across the controllers since they're all in the same "package controllers".

For that I think this can work :
each controller will get a unique get log sign.:

func cinderApiLog(ctx context.Context) logr.Logger ..

//usage :

func (..) Reconcile..ctrl.Result, _err error) { log := cinderApiLog(ctx)

How's that ?

ASBishop · 2023-09-20T16:17:05Z

controllers/cinder_controller.go

@@ -278,7 +280,8 @@ func (r *CinderReconciler) SetupWithManager(mgr ctrl.Manager) error {
 }

 func (r *CinderReconciler) reconcileDelete(ctx context.Context, instance *cinderv1beta1.Cinder, helper *helper.Helper) (ctrl.Result, error) {
-	r.Log.Info(fmt.Sprintf("Reconciling Service '%s' delete", instance.Name))
+	log := GetLog(ctx, "Cinder")


This is an example of what I referred to in my previous comment.

This represents a PoC that offers an alternative approach to pull request openstack-k8s-operators#258. Here is a sample of the outputs: 2023-09-21T08:09:42-07:00 INFO controllers.Cinder Reconciling Service 'cinder' {"controller": "cinder", "controllerGroup": "cinder.openstack.org", "controllerKind": "Cinder", "Cinder": {"na me":"cinder","namespace":"openstack"}, "namespace": "openstack", "name": "cinder", "reconcileID": "90ede6d8-c15a-44cb-b0b0-7e139e831f02"} 2023-09-21T08:09:42-07:00 INFO controllers.Cinder Reconciling Service 'cinder' init {"controller": "cinder", "controllerGroup": "cinder.openstack.org", "controllerKind": "Cinder", "Cinde r": {"name":"cinder","namespace":"openstack"}, "namespace": "openstack", "name": "cinder", "reconcileID": "90ede6d8-c15a-44cb-b0b0-7e139e831f02"} 2023-09-21T08:09:42-07:00 INFO controllers.Cinder Reconciled Service 'cinder' init successfully {"controller": "cinder", "controllerGroup": "cinder.openstack.org", "controllerKind": "Cinder" , "Cinder": {"name":"cinder","namespace":"openstack"}, "namespace": "openstack", "name": "cinder", "reconcileID": "90ede6d8-c15a-44cb-b0b0-7e139e831f02"} 2023-09-21T08:09:42-07:00 INFO controllers.Cinder Reconciling Service 'cinder' update {"controller": "cinder", "controllerGroup": "cinder.openstack.org", "controllerKind": "Cinder", "Cinde r": {"name":"cinder","namespace":"openstack"}, "namespace": "openstack", "name": "cinder", "reconcileID": "90ede6d8-c15a-44cb-b0b0-7e139e831f02"} 2023-09-21T08:09:42-07:00 INFO controllers.Cinder Reconciled Service 'cinder' update successfully {"controller": "cinder", "controllerGroup": "cinder.openstack.org", "controllerKind": "Cinder" , "Cinder": {"name":"cinder","namespace":"openstack"}, "namespace": "openstack", "name": "cinder", "reconcileID": "90ede6d8-c15a-44cb-b0b0-7e139e831f02"} 2023-09-21T08:09:42-07:00 INFO controllers.Cinder Reconciling Service 'cinder' upgrade {"controller": "cinder", "controllerGroup": "cinder.openstack.org", "controllerKind": "Cinder", "Cinde r": {"name":"cinder","namespace":"openstack"}, "namespace": "openstack", "name": "cinder", "reconcileID": "90ede6d8-c15a-44cb-b0b0-7e139e831f02"} 2023-09-21T08:09:42-07:00 INFO controllers.Cinder Reconciled Service 'cinder' upgrade successfully {"controller": "cinder", "controllerGroup": "cinder.openstack.org", "controllerKind": "Cinder", "Cinder": {"name":"cinder","namespace":"openstack"}, "namespace": "openstack", "name": "cinder", "reconcileID": "90ede6d8-c15a-44cb-b0b0-7e139e831f02"} 2023-09-21T08:09:42-07:00 INFO controllers.Cinder Reconciled Service 'cinder' successfully {"controller": "cinder", "controllerGroup": "cinder.openstack.org", "controllerKind": "Cinder" , "Cinder": {"name":"cinder","namespace":"openstack"}, "namespace": "openstack", "name": "cinder", "reconcileID": "90ede6d8-c15a-44cb-b0b0-7e139e831f02"} 2023-09-21T08:11:52-07:00 INFO controllers.CinderAPI Reconciling Service 'cinder-api' {"controller": "cinderapi", "controllerGroup": "cinder.openstack.org", "controllerKind": "CinderAPI", "CinderAPI": {"name":"cinder-api","namespace":"openstack"}, "namespace": "openstack", "name": "cinder-api", "reconcileID": "baa7a2f5-392a-4b7b-bf8a-1c4ca1b77183"} 2023-09-21T08:11:52-07:00 INFO controllers.CinderAPI Reconciling Service 'cinder-api' init {"controller": "cinderapi", "controllerGroup": "cinder.openstack.org", "controllerKind": "CinderAPI", "CinderAPI": {"name":"cinder-api","namespace":"openstack"}, "namespace": "openstack", "name": "cinder-api", "reconcileID": "baa7a2f5-392a-4b7b-bf8a-1c4ca1b77183"} 2023-09-21T08:11:52-07:00 INFO controllers.CinderAPI Service cinder-internal - updated {"controller": "cinderapi", "controllerGroup": "cinder.openstack.org", "controllerKind": "CinderAPI", "CinderAPI": {"name":"cinder-api","namespace":"openstack"}, "namespace": "openstack", "name": "cinder-api", "reconcileID": "baa7a2f5-392a-4b7b-bf8a-1c4ca1b77183"} 2023-09-21T08:11:52-07:00 INFO controllers.CinderAPI Service cinder-public - updated {"controller": "cinderapi", "controllerGroup": "cinder.openstack.org", "controllerKind": "CinderAPI", "CinderAPI": {"name":"cinder-api","namespace":"openstack"}, "namespace": "openstack", "name": "cinder-api", "reconcileID": "baa7a2f5-392a-4b7b-bf8a-1c4ca1b77183"} 2023-09-21T08:11:52-07:00 INFO controllers.CinderAPI Route cinder-public - updated {"controller": "cinderapi", "controllerGroup": "cinder.openstack.org", "controllerKind": "CinderAPI", "CinderAPI": {"name":"cinder-api","namespace":"openstack"}, "namespace": "openstack", "name": "cinder-api", "reconcileID": "baa7a2f5-392a-4b7b-bf8a-1c4ca1b77183"} 2023-09-21T08:11:52-07:00 INFO controllers.CinderAPI Reconciled Service 'cinder-api' init successfully {"controller": "cinderapi", "controllerGroup": "cinder.openstack.org", "controllerKind": "CinderAPI", "CinderAPI": {"name":"cinder-api","namespace":"openstack"}, "namespace": "openstack", "name": "cinder-api", "reconcileID": "baa7a2f5-392a-4b7b-bf8a-1c4ca1b77183"}

Akrog

Thanks for all the hard work to improve our logging :-)

Akrog · 2023-10-04T14:06:23Z

controllers/cinder_controller.go

-func (r *CinderReconciler) GetLogger() logr.Logger {
-	return r.Log
+// getLog returns a logger object with a logging prefix of "conrollers.name" and aditional controller context fields
+func cinderLog(ctx context.Context) logr.Logger {


-1: Please make this a struct method like it was before, all you need to do is add the new method argument.

func (r *CinderReconciler) GetLogger(ctx context.Context) logr.Logger {

That way the name remains the same regardless of the controller we are in and we'll always do log := r.GetLogger(ctx)

Akrog

I think the code is ready to be merged, could you squash all the commits into 1 please?
And rebase it, because it's in conflict.

ASBishop

This PR is moving in the right direction, but I want us to consider another update.

I also agree with Gorka's note about rebasing and squashing the commits.

controllers/cinder_controller.go

ASBishop · 2023-10-05T16:30:14Z

controllers/cinder_controller.go

@@ -138,7 +137,7 @@ func (r *CinderReconciler) Reconcile(ctx context.Context, req ctrl.Request) (res
 		r.Client,
 		r.Kclient,
 		r.Scheme,
-		r.Log,
+		log,


I really like the idea of adding the logger function to the helper !!!

But can we call it Log (capital 'L')? See how it will be referenced in a comment below.

ASBishop · 2023-10-05T16:32:33Z

controllers/cinder_controller.go

@@ -278,7 +280,8 @@ func (r *CinderReconciler) SetupWithManager(mgr ctrl.Manager) error {
 }

 func (r *CinderReconciler) reconcileDelete(ctx context.Context, instance *cinderv1beta1.Cinder, helper *helper.Helper) (ctrl.Result, error) {
-	r.Log.Info(fmt.Sprintf("Reconciling Service '%s' delete", instance.Name))
+	log := r.getLog(ctx)


Why not use the logger that's available in the helper?

helper.Log.Info(...)

For me the Helper is a dumping ground of unrelated utility functions. See https://wiki.c2.com/?AbuseOfUtilityClasses So my ultimate goal is not to add things to it but actually dissolve it in the long run.

I had a stab at having a separate logger package openstack-k8s-operators/lib-common#125 but it turned out that we already get a proper logger via the ctx anyway so that package would be fairly empty.

So where does that leave us? It seems reasonable for every controller to have its own logger function, and the question is how to provide easy access to that function. I agree the Helper shouldn't be a dumping ground, but if we avoid using it then we'll need some other way to forward.

the ctx is already passed around and the ctx already contains a logger to use. So the r.getLog(ctx) is good for me.

I.e for me the difference between helper.Log.Info(...) an r.getLog(ctx).Info() is that ctx is the framework's way to pass a logger to us and we already have the context in most places, so pulling the logger out of context and adding it to the helper seems like an unnecessary complication to me.

ASBishop · 2023-10-05T16:34:23Z

controllers/cinder_controller.go

@@ -309,7 +312,8 @@ func (r *CinderReconciler) reconcileInit(
 	serviceLabels map[string]string,
 	serviceAnnotations map[string]string,
 ) (ctrl.Result, error) {
-	r.Log.Info(fmt.Sprintf("Reconciling Service '%s' init", instance.Name))
+	log := r.getLog(ctx)
+	log.Info(fmt.Sprintf("Reconciling Service '%s' init", instance.Name))


Same as before. Just replace "r.Log()" with "helper.Log()"

ASBishop

+1 from me, though I'd like to see feedback from @Akrog .

Also see my comment on how we might take the opportunity to remove the Log element from helpers.

ASBishop · 2023-10-24T19:17:58Z

controllers/cinder_controller.go

@@ -116,7 +115,7 @@ type CinderReconciler struct {

 // Reconcile -
 func (r *CinderReconciler) Reconcile(ctx context.Context, req ctrl.Request) (result ctrl.Result, _err error) {
-	_ = log.FromContext(ctx)
+	Log := r.GetLogger(ctx)


I still wish it was possible to pass the logger function down the call stack in order to minimize the number of places that have to call this function. But maybe I just need to get used to a new (to me) convention.

ASBishop · 2023-10-24T19:22:42Z

controllers/cinder_controller.go

@@ -137,7 +136,7 @@ func (r *CinderReconciler) Reconcile(ctx context.Context, req ctrl.Request) (res
 		r.Client,
 		r.Kclient,
 		r.Scheme,
-		r.Log,
+		Log,


@gibizer I recall you saying you'd like to reduce (eliminate?) our use of helpers. With this PR, the Log element in the helper is no longer used by the controller, but we have to supply one in order create the helper. It looks like we have an opportunity to remove the Log from the helper (since nobody will use it), but I don't know how to coordinate doing that across all the repos that use the current helper. Any thoughts on that?

I agree, we could have had a PR to remove the parameter in lib-common, and then bump its pinning here in this same PR so we could remove the passing of the parameter in one go.

With the current approach we need to:

Merge this PR

Remove the code from lib-common that requires the logger argument

Update the pinning in all the operators at the same time we remove the passing of the argument.

Our current approach seems more painful, but for the shake of getting things done and keep moving we can merge it.

controllers/cinder_controller.go

Akrog

/lgtm

Akrog · 2023-11-06T18:58:34Z

controllers/cinder_controller.go

@@ -137,7 +136,7 @@ func (r *CinderReconciler) Reconcile(ctx context.Context, req ctrl.Request) (res
 		r.Client,
 		r.Kclient,
 		r.Scheme,
-		r.Log,
+		Log,


I agree, we could have had a PR to remove the parameter in lib-common, and then bump its pinning here in this same PR so we could remove the passing of the parameter in one go.

With the current approach we need to:

Merge this PR

Remove the code from lib-common that requires the logger argument

Update the pinning in all the operators at the same time we remove the passing of the argument.

Our current approach seems more painful, but for the shake of getting things done and keep moving we can merge it.

pinikomarov · 2023-11-07T10:13:30Z

recheck

controllers/cinder_controller.go

ASBishop

+1

ASBishop · 2023-12-14T13:50:24Z

/retest

openshift-ci · 2023-12-14T14:48:58Z

@pinikomarov: The following test failed, say /retest to rerun all failed tests or /retest-required to rerun all mandatory failed tests:

Test name	Commit	Details	Required	Rerun command
ci/prow/unit	`b2b7e24`	link	true	`/test unit`

Full PR test history. Your PR dashboard.

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository. I understand the commands that are listed here.

fix client.list params update test logging

openshift-ci · 2024-01-04T18:13:48Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: Akrog, ASBishop, pinikomarov

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~~ [ASBishop,Akrog]

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

openshift-ci bot added do-not-merge/work-in-progress needs-ok-to-test labels Sep 2, 2023

Akrog requested changes Sep 5, 2023

View reviewed changes

openshift-ci bot assigned Akrog Sep 5, 2023

ASBishop reviewed Sep 20, 2023

View reviewed changes

openshift-merge-robot added the needs-rebase label Sep 30, 2023

pinikomarov marked this pull request as ready for review October 4, 2023 13:08

openshift-ci bot removed the do-not-merge/work-in-progress label Oct 4, 2023

openshift-ci bot requested review from ASBishop and frenzyfriday October 4, 2023 13:08

Akrog requested changes Oct 4, 2023

View reviewed changes

Akrog reviewed Oct 5, 2023

View reviewed changes

ASBishop requested changes Oct 5, 2023

View reviewed changes

openshift-ci bot assigned ASBishop Oct 5, 2023

pinikomarov force-pushed the structured_logging branch from 9368890 to fa51328 Compare October 8, 2023 00:31

pinikomarov force-pushed the structured_logging branch from fa51328 to 0656194 Compare October 19, 2023 09:19

openshift-merge-robot removed the needs-rebase label Oct 19, 2023

pinikomarov force-pushed the structured_logging branch from 0656194 to be6d470 Compare October 24, 2023 11:31

ASBishop reviewed Oct 24, 2023

View reviewed changes

olliewalsh requested changes Oct 24, 2023

View reviewed changes

controllers/cinder_controller.go Outdated Show resolved Hide resolved

openshift-ci bot assigned olliewalsh Oct 24, 2023

Akrog approved these changes Nov 6, 2023

View reviewed changes

openshift-ci bot added lgtm approved labels Nov 6, 2023

pinikomarov force-pushed the structured_logging branch from b2b7e24 to c845ee1 Compare November 7, 2023 13:25

openshift-ci bot removed the lgtm label Nov 7, 2023

openshift-merge-robot added the needs-rebase label Nov 7, 2023

pinikomarov force-pushed the structured_logging branch 2 times, most recently from c98a06a to 5c00980 Compare November 7, 2023 14:54

openshift-merge-robot removed the needs-rebase label Nov 7, 2023

pinikomarov force-pushed the structured_logging branch from 643322b to 5c00980 Compare November 7, 2023 15:00

openshift-merge-robot added the needs-rebase label Nov 7, 2023

pinikomarov force-pushed the structured_logging branch 2 times, most recently from 6b453d1 to 7be72e3 Compare November 8, 2023 22:31

openshift-merge-robot removed the needs-rebase label Nov 8, 2023

pinikomarov force-pushed the structured_logging branch from 7be72e3 to 52d9e8d Compare November 8, 2023 22:35

openshift-merge-robot added the needs-rebase label Nov 8, 2023

pinikomarov force-pushed the structured_logging branch from 52d9e8d to 6ebe581 Compare November 8, 2023 22:38

openshift-merge-robot removed the needs-rebase label Nov 8, 2023

pinikomarov force-pushed the structured_logging branch from 6ebe581 to 106d164 Compare November 8, 2023 23:30

ASBishop reviewed Nov 9, 2023

View reviewed changes

controllers/cinder_controller.go Outdated Show resolved Hide resolved

pinikomarov force-pushed the structured_logging branch from 106d164 to 9de278d Compare November 12, 2023 22:36

pinikomarov force-pushed the structured_logging branch from 9de278d to 3a466a1 Compare December 4, 2023 23:01

ASBishop reviewed Dec 14, 2023

View reviewed changes

switch to structured logging

375ec51

fix client.list params update test logging

pinikomarov force-pushed the structured_logging branch from 3a466a1 to 375ec51 Compare December 18, 2023 22:57

ASBishop approved these changes Jan 4, 2024

View reviewed changes

openshift-ci bot added the lgtm label Jan 4, 2024

openshift-merge-bot bot merged commit fef9f1c into openstack-k8s-operators:main Jan 4, 2024
7 checks passed

switch to structured logging #258

switch to structured logging #258

Conversation

pinikomarov commented Sep 2, 2023 • edited Loading

openshift-ci bot commented Sep 2, 2023

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

pinikomarov Sep 26, 2023 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

pinikomarov Sep 29, 2023 • 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

Akrog left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Akrog left a comment • edited Loading

Choose a reason for hiding this comment

ASBishop left a 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

gibizer Oct 10, 2023 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ASBishop left a 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

Akrog left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

pinikomarov commented Nov 7, 2023

ASBishop left a comment

Choose a reason for hiding this comment

ASBishop commented Dec 14, 2023

openshift-ci bot commented Dec 14, 2023 • edited Loading

openshift-ci bot commented Jan 4, 2024

pinikomarov commented Sep 2, 2023 •

edited

Loading

pinikomarov Sep 26, 2023 •

edited

Loading

pinikomarov Sep 29, 2023 •

edited

Loading

Akrog left a comment •

edited

Loading

gibizer Oct 10, 2023 •

edited

Loading

openshift-ci bot commented Dec 14, 2023 •

edited

Loading