chore: structured logging for pkg/controller #1629

jairuigou · 2024-05-28T12:48:45Z

Ⅰ. Describe what this PR does

Support structured logging for pkg/controller

Ⅱ. Does this pull request fix one issue?

#1551

Ⅲ. Describe how to verify it

use k8s.io/klog/hack/tools/logcheck
logcheck -check-structured ./pkg/controller/...

Ⅳ. Special notes for reviews

kruise-bot · 2024-05-28T12:49:02Z

Welcome @jairuigou! It looks like this is your first PR to openkruise/kruise 🎉

furykerry

plz pass structured values directly in the structured logs calls

furykerry · 2024-06-04T08:16:28Z

pkg/controller/advancedcronjob/advancedcronjob_broadcastjob_controller.go

 			} else {
-				klog.V(0).Info("deleted old failed broadcastjob", "job", job, req.NamespacedName)
+				klog.InfoS("Deleted old failed BroadcastJob", "olbFailedBroadcastJob", klog.KObj(job), "advancedCronJob", req.NamespacedName)


olbFailedBroadcastJob -》 oldFailedBroadcastJob

furykerry · 2024-06-04T08:21:05Z

pkg/controller/advancedcronjob/advancedcronjob_broadcastjob_controller.go

@@ -292,7 +292,7 @@ func (r *ReconcileAdvancedCronJob) reconcileBroadcastJob(ctx context.Context, re
 		tooLate = missedRun.Add(time.Duration(*advancedCronJob.Spec.StartingDeadlineSeconds) * time.Second).Before(now)
 	}
 	if tooLate {
-		klog.V(1).Info("missed starting deadline for last run, sleeping till next", "current run", missedRun, req.NamespacedName)
+		klog.V(1).InfoS("Missed starting deadline for last run, sleeping till next current run", "missedRun", missedRun, "advancedCronJob", req.NamespacedName)


"Missed starting deadline for last run, sleeping till next current run" -> "Missed starting deadline for last run, sleeping till next run"

furykerry · 2024-06-04T08:40:37Z

pkg/controller/advancedcronjob/advancedcronjob_job_controller.go

@@ -285,7 +285,7 @@ func (r *ReconcileAdvancedCronJob) reconcileJob(ctx context.Context, req ctrl.Re
 		If we've missed a run, and we're still within the deadline to start it, we'll need to run a job.
 	*/
 	if missedRun.IsZero() {
-		klog.V(1).Info("no upcoming scheduled times, sleeping until next now ", now, " and next run ", nextRun, req.NamespacedName)
+		klog.V(1).InfoS("No upcoming scheduled times, sleeping until next now and next run", "nextNow", now, "nextRun", nextRun, "advancedCronJob", req.NamespacedName)


"No upcoming scheduled times, sleeping until next now and next run" -> "No upcoming scheduled times, sleeping until next run"

and replace "nextNow" with "now"

furykerry · 2024-06-04T08:40:53Z

pkg/controller/advancedcronjob/advancedcronjob_broadcastjob_controller.go

@@ -282,7 +282,7 @@ func (r *ReconcileAdvancedCronJob) reconcileBroadcastJob(ctx context.Context, re
 		If we've missed a run, and we're still within the deadline to start it, we'll need to run a job.
 	*/
 	if missedRun.IsZero() {
-		klog.V(1).Info("no upcoming scheduled times, sleeping until next now ", now, " and next run ", nextRun, req.NamespacedName)
+		klog.V(1).InfoS("No upcoming scheduled times, sleeping until next now and next run", "nextNow", now, "nextRun", nextRun, "advancedCronJob", req.NamespacedName)


"no upcoming scheduled times, sleeping until next now " -》 "No upcoming scheduled times, sleeping until next run"

and replace "nextNow" with "now"

furykerry · 2024-06-04T08:57:21Z

pkg/controller/broadcastjob/broadcastjob_controller.go

 		return reconcile.Result{}, err
 	}

 	if scaleSatisfied, unsatisfiedDuration, scaleDirtyPods := scaleExpectations.SatisfiedExpectations(request.String()); !scaleSatisfied {
 		if unsatisfiedDuration >= expectations.ExpectationTimeout {
-			klog.Warningf("Expectation unsatisfied overtime for bcj %v, scaleDirtyPods=%v, overtime=%v", request.String(), scaleDirtyPods, unsatisfiedDuration)
+			klog.InfoS("Expectation unsatisfied overtime for BroadcastJob", "broadcastJob", request.String(), "scaleDirtyPods", scaleDirtyPods, "overtime", unsatisfiedDuration)


plz pass structured value directly without .string(), replace request.String() with request

furykerry · 2024-06-04T10:20:44Z

pkg/controller/imagepulljob/imagepulljob_controller.go

 		return reconcile.Result{RequeueAfter: expectations.ExpectationTimeout - unsatisfiedDuration}, nil
 	}

 	// If resourceVersion expectations have not satisfied yet, just skip this reconcile
 	resourceVersionExpectations.Observe(job)
 	if isSatisfied, unsatisfiedDuration := resourceVersionExpectations.IsSatisfied(job); !isSatisfied {
 		if unsatisfiedDuration >= expectations.ExpectationTimeout {
-			klog.Warningf("Expectation unsatisfied overtime for %v, timeout=%v", request.String(), unsatisfiedDuration)
+			klog.InfoS("Expectation unsatisfied overtime", "imagePullJob", request.String(), "timeout", unsatisfiedDuration)


replace request.String() with request

furykerry · 2024-06-04T10:20:50Z

pkg/controller/imagepulljob/imagepulljob_controller.go

 			return reconcile.Result{}, nil
 		}
-		klog.V(4).Infof("Not satisfied resourceVersion for %v", request.String())
+		klog.V(4).InfoS("Not satisfied resourceVersion", "imagePullJob", request.String())


replace request.String() with request

furykerry · 2024-06-04T10:21:02Z

pkg/controller/imagepulljob/imagepulljob_controller.go

@@ -238,10 +238,10 @@ func (r *ReconcileImagePullJob) Reconcile(_ context.Context, request reconcile.R
 		resourceVersionExpectations.Observe(nodeImage)
 		if isSatisfied, unsatisfiedDuration := resourceVersionExpectations.IsSatisfied(nodeImage); !isSatisfied {
 			if unsatisfiedDuration >= expectations.ExpectationTimeout {
-				klog.Warningf("Expectation unsatisfied overtime for %v, wait for NodeImage %v updating, timeout=%v", request.String(), nodeImage.Name, unsatisfiedDuration)
+				klog.InfoS("Expectation unsatisfied overtime, waiting for NodeImage updating", "imagePullJob", request.String(), "nodeImageName", nodeImage.Name, "timeout", unsatisfiedDuration)


replace request.String() with request

furykerry · 2024-06-04T10:21:11Z

pkg/controller/imagepulljob/imagepulljob_controller.go

 				return reconcile.Result{}, nil
 			}
-			klog.V(4).Infof("Not satisfied resourceVersion for %v, wait for NodeImage %v updating", request.String(), nodeImage.Name)
+			klog.V(4).InfoS("Not satisfied resourceVersion, waiting for NodeImage updating", "imagePullJob", request.String(), "nodeImageName", nodeImage.Name)


replace request.String() with request

furykerry · 2024-06-04T10:23:18Z

pkg/controller/nodeimage/nodeimage_controller.go

 	var requeueMsg string
 	defer func() {
 		if err != nil {
-			klog.Warningf("Failed to process NodeImage %v err %v, elapsedTime %v", request.Name, time.Since(start), err)
+			klog.InfoS("Failed to process NodeImage", "nodeImageName", request.Name, "elapsedTime", time.Since(start), "err", err)


replace InfoS with ErrorS

codecov · 2024-06-11T05:21:03Z

Codecov Report

Attention: Patch coverage is 35.91160% with 348 lines in your changes missing coverage. Please review.

Project coverage is 49.46%. Comparing base (0d0031a) to head (32a6fb0).
Report is 48 commits behind head on master.

Files	Patch %	Lines
pkg/controller/daemonset/daemonset_controller.go	24.32%	28 Missing ⚠️
...controller/broadcastjob/broadcastjob_controller.go	35.48%	20 Missing ⚠️
...cronjob/advancedcronjob_broadcastjob_controller.go	11.11%	16 Missing ⚠️
.../advancedcronjob/advancedcronjob_job_controller.go	11.11%	16 Missing ⚠️
...controller/imagepulljob/imagepulljob_controller.go	0.00%	16 Missing ⚠️
...sistentpodstate/persistent_pod_state_controller.go	18.75%	13 Missing ⚠️
pkg/controller/cloneset/cloneset_controller.go	45.45%	12 Missing ⚠️
pkg/controller/sidecarset/sidecarset_processor.go	45.45%	12 Missing ⚠️
...oller/statefulset/statefulset_predownload_image.go	0.00%	12 Missing ⚠️
...roller/workloadspread/workloadspread_controller.go	25.00%	12 Missing ⚠️
... and 46 more

Additional details and impacted files

@@            Coverage Diff             @@
##           master    #1629      +/-   ##
==========================================
+ Coverage   47.91%   49.46%   +1.54%     
==========================================
  Files         162      183      +21     
  Lines       23491    18997    -4494     
==========================================
- Hits        11256     9396    -1860     
+ Misses      11014     8378    -2636     
- Partials     1221     1223       +2

Flag	Coverage Δ
unittests	`49.46% <35.91%> (+1.54%)`	⬆️

Flags with carried forward coverage won't be shown. Click here to find out more.

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

furykerry · 2024-06-13T09:30:48Z

plz squash the commits into one

furykerry · 2024-06-14T11:04:26Z

/lgtm

furykerry

plz also rebase the master for changes

furykerry · 2024-06-21T07:05:42Z

pkg/controller/daemonset/daemonset_controller.go

 		return false
 	}

 	for _, pod := range pods {
 		dsc.resourceVersionExpectations.Observe(pod)
 		if isSatisfied, unsatisfiedDuration := dsc.resourceVersionExpectations.IsSatisfied(pod); !isSatisfied {
 			if unsatisfiedDuration >= kruiseExpectations.ExpectationTimeout {
-				klog.Errorf("Expectation unsatisfied resourceVersion overtime for %v, wait for pod %v updating, timeout=%v", dsKey, pod.Name, unsatisfiedDuration)
+				klog.ErrorS(fmt.Errorf("expectation unsatisfied resourceVersion overtime for DaemonSet, wait for pod updating"),


plz just pass nil as error in the ErrorS,

plz change similar logging lines too, pass nil error to ErrorS if no explicit error is available in the context

Signed-off-by: jairui <jairuigou@gmail.com>

furykerry · 2024-06-24T05:55:46Z

/lgtm

zmberg · 2024-06-24T06:01:04Z

/approve

kruise-bot · 2024-06-24T06:01:12Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: zmberg

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~~ [zmberg]

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

kruise-bot requested review from FillZpp, shiyan2016 and zmberg May 28, 2024 12:48

kruise-bot added the size/XXL label May 28, 2024

furykerry reviewed Jun 4, 2024

View reviewed changes

jairuigou force-pushed the structured-log-for-controller branch 2 times, most recently from f123e71 to bd4d38e Compare June 14, 2024 08:43

furykerry closed this Jun 14, 2024

furykerry reopened this Jun 14, 2024

kruise-bot added the needs-rebase label Jun 18, 2024

furykerry reviewed Jun 21, 2024

View reviewed changes

support structured logging for pkg/controller

32a6fb0

Signed-off-by: jairui <jairuigou@gmail.com>

jairuigou force-pushed the structured-log-for-controller branch from bd4d38e to 32a6fb0 Compare June 23, 2024 07:14

kruise-bot removed the needs-rebase label Jun 23, 2024

kruise-bot assigned furykerry Jun 24, 2024

kruise-bot added the lgtm label Jun 24, 2024

kruise-bot added the approved label Jun 24, 2024

kruise-bot merged commit f0f6eef into openkruise:master Jun 24, 2024
38 of 40 checks passed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

chore: structured logging for pkg/controller #1629

chore: structured logging for pkg/controller #1629

jairuigou commented May 28, 2024

kruise-bot commented May 28, 2024

furykerry left a comment

furykerry Jun 4, 2024

furykerry Jun 4, 2024

furykerry Jun 4, 2024

furykerry Jun 4, 2024

furykerry Jun 4, 2024

furykerry Jun 4, 2024

furykerry Jun 4, 2024

furykerry Jun 4, 2024

furykerry Jun 4, 2024

furykerry Jun 4, 2024

codecov bot commented Jun 11, 2024 •

edited

Loading

furykerry commented Jun 13, 2024

furykerry commented Jun 14, 2024

furykerry left a comment

furykerry Jun 21, 2024

jairuigou Jun 23, 2024

furykerry commented Jun 24, 2024

zmberg commented Jun 24, 2024

kruise-bot commented Jun 24, 2024

chore: structured logging for pkg/controller #1629

chore: structured logging for pkg/controller #1629

Conversation

jairuigou commented May 28, 2024

Ⅰ. Describe what this PR does

Ⅱ. Does this pull request fix one issue?

Ⅲ. Describe how to verify it

Ⅳ. Special notes for reviews

kruise-bot commented May 28, 2024

furykerry 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

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

codecov bot commented Jun 11, 2024 • edited Loading

Codecov Report

furykerry commented Jun 13, 2024

furykerry commented Jun 14, 2024

furykerry left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

furykerry commented Jun 24, 2024

zmberg commented Jun 24, 2024

kruise-bot commented Jun 24, 2024

codecov bot commented Jun 11, 2024 •

edited

Loading