[Refactor][1/n] Replace logrus with logr to keep logging consistent #1835

rueian · 2024-01-16T16:29:00Z

Why are these changes needed?

We currently write logs through two different interfaces, the logr and the logrus.

Following the discussion #1793 (comment), we would like to revisit and unify our logging format for further usages, which requires a unified structure format, such as filtering logs by a k8s namespace.

This PR replaces the usages of logrus with the logr, which is recommended by the kubebuilder, to unify our logging format. I will add namespace logging in the next PR.

Related issue number

Checks

I've made sure the tests are passing.
Testing Strategy
- Unit tests
- Manual tests
- This PR is not tested :(

rueian · 2024-01-16T16:30:46Z

ray-operator/controllers/ray/common/ingress.go

@@ -87,7 +86,7 @@ func BuildIngressForHeadService(cluster rayv1.RayCluster) (*networkingv1.Ingress
 	// Get ingress class name from rayCluster annotations. this is a required field to use ingress.
 	ingressClassName, ok := cluster.Annotations[IngressClassAnnotationKey]
 	if !ok {
-		logrus.Warn(fmt.Sprintf("ingress class annotation is not set for cluster %s/%s", cluster.Namespace, cluster.Name))
+		log.Info(fmt.Sprintf("ingress class annotation is not set for cluster %s/%s", cluster.Namespace, cluster.Name))


This log variable is initialized at

kuberay/ray-operator/controllers/ray/common/pod.go

Line 37 in af5d639

var log = logf.Log.WithName("controllers").WithName("RayCluster")

rueian · 2024-01-16T16:31:53Z

ray-operator/controllers/ray/common/pod.go

@@ -34,7 +34,7 @@ const (
 	EnableInitContainerInjectionEnvKey = "ENABLE_INIT_CONTAINER_INJECTION"
 )

-var log = logf.Log.WithName("RayCluster-Controller")
+var log = logf.Log.WithName("controllers").WithName("RayCluster")


Make it consistent with

kuberay/ray-operator/controllers/ray/raycluster_controller.go

Line 105 in c55f3cc

log := ctrl.Log.WithName("controllers").WithName("RayCluster")

kevin85421

Nice! I like this refactor PR. cc @astefanutti would you mind reviewing this PR? Thanks!

kevin85421 · 2024-01-16T22:13:16Z

ray-operator/controllers/ray/utils/util.go

@@ -32,6 +31,8 @@ const (
 	DefaultDomainName   = "cluster.local"
 )

+var log = logf.Log.WithName("controllers").WithName("RayCluster")


It seems to be possible for RayJob/RayService controllers to call utility functions.

It will be better to use log := ctrl.LoggerFrom(ctx) mentioned by @astefanutti.

astefanutti · 2024-01-17T08:33:23Z

ray-operator/controllers/ray/common/ingress.go

@@ -87,7 +86,7 @@ func BuildIngressForHeadService(cluster rayv1.RayCluster) (*networkingv1.Ingress
 	// Get ingress class name from rayCluster annotations. this is a required field to use ingress.
 	ingressClassName, ok := cluster.Annotations[IngressClassAnnotationKey]
 	if !ok {
-		logrus.Warn(fmt.Sprintf("ingress class annotation is not set for cluster %s/%s", cluster.Namespace, cluster.Name))
+		log.Info(fmt.Sprintf("ingress class annotation is not set for cluster %s/%s", cluster.Namespace, cluster.Name))


It'd be preferable to avoid string formatting and use the structured form, e.g.:

log.Info("ingress class annotation is not set for cluster", cluster.Namespace, cluster.Name)

Maybe you're already planning to do it in a separate PR.

Well, I am planning to add the namespace to the structured form, but I am not sure whether should we move all the logging parameters to the structured form. IMHO, the structured fields are subject to special purposes only such as filtering. Moving all parameters out from the message may reduce readability.

Right, having both the formatted message and the structured info sounds reasonable too.

astefanutti · 2024-01-17T08:35:06Z

ray-operator/controllers/ray/utils/util.go

@@ -32,6 +31,8 @@ const (
 	DefaultDomainName   = "cluster.local"
 )

+var log = logf.Log.WithName("controllers").WithName("RayCluster")


For the case where utility functions are called by multiple controllers, it may be preferable to use the logger propagated in the context instead, e.g.:

log := ctrl.LoggerFrom(ctx)

astefanutti · 2024-01-17T08:47:11Z

ray-operator/controllers/ray/common/ingress.go

@@ -87,7 +86,7 @@ func BuildIngressForHeadService(cluster rayv1.RayCluster) (*networkingv1.Ingress
 	// Get ingress class name from rayCluster annotations. this is a required field to use ingress.
 	ingressClassName, ok := cluster.Annotations[IngressClassAnnotationKey]
 	if !ok {
-		logrus.Warn(fmt.Sprintf("ingress class annotation is not set for cluster %s/%s", cluster.Namespace, cluster.Name))
+		log.Info(fmt.Sprintf("ingress class annotation is not set for cluster %s/%s", cluster.Namespace, cluster.Name))


Note, there is the logger provided by controller-runtime that can be retrieved from the context, e.g.:

log := ctrl.LoggerFrom(ctx)

This contains the reconciliation request id, and can be customised with common key / value pairs (e.g. namespace and name) with the LogConstructor option of the controller builder.

But a global variable can be a good approximation at the moment.

rueian · 2024-01-20T12:54:53Z

Hi @astefanutti, @kevin85421

I have changed to use log := ctrl.LoggerFrom(ctx) in 4bbbc3a

kevin85421 · 2024-01-23T01:47:44Z

Would you mind rebasing with the master branch? Thanks!

astefanutti

LGTM, thanks!

astefanutti · 2024-01-25T08:55:18Z

ray-operator/controllers/ray/raycluster_controller.go

@@ -164,6 +164,7 @@ type RayClusterReconcilerOptions struct {
 // Reconcile used to bridge the desired state with the current state
 func (r *RayClusterReconciler) Reconcile(ctx context.Context, request ctrl.Request) (ctrl.Result, error) {
 	var err error
+	ctx = ctrl.LoggerInto(ctx, r.Log) // TODO: add reqeust namespace here


nit: "reqeust" -> "request"

kevin85421

I have several questions:

All RayCluster, RayJob, and RayService reconcilers seem to be running in a single process.
(Not sure) Because the default value of config.ReconcileConcurrency is 1, it seems to be only 1 thread for all reconcilers.
What would happen if config.ReconcileConcurrency were set to more than 1? If the RayCluster and RayService reconcilers were to run concurrently and both call ctx = ctrl.LoggerInto(ctx, r.Log), could that lead to a race condition when calling ctrl.LoggerFrom(ctx)?

astefanutti · 2024-01-26T09:57:45Z

I have several questions:

All RayCluster, RayJob, and RayService reconcilers seem to be running in a single process.

(Not sure) Because the default value of config.ReconcileConcurrency is 1, it seems to be only 1 thread for all reconcilers.

the MaxConcurrentReconciles option controls the maximum number of routines that concurrently process items from a controller event queue. This is per controller, so at the moment, with MaxConcurrentReconciles defaulted to 1, each of the RayCluster, RayJob and RayService controllers Reconcile method is called by a single routine, but independently from each other.

What would happen if config.ReconcileConcurrency were set to more than 1? If the RayCluster and RayService reconcilers were to run concurrently and both call ctx = ctrl.LoggerInto(ctx, r.Log), could that lead to a race condition when calling ctrl.LoggerFrom(ctx)?

ctrl.LoggerInto returns a new context, that's a child of the provided one, so the logger that's set is only local to a single Reconcile method call, and all the methods down the call stack where it's passed as argument. So every concurrent invocation will have its own logger instance.

rueian · 2024-01-26T16:21:00Z

Thank you @astefanutti for your detailed explanation!

Hi @kevin85421, The ctx variable is independent for each Reconcile(ctx context.Context, request ctrl.Request) and the ctrl.LoggerInto will not modify the original context. Therefore, there will be no race between concurrent calls to ctx = ctrl.LoggerInto(ctx, r.Log) and ctrl.LoggerFrom(ctx).

Here is a quick concurrent test to simulate the situation:

func test(ctx context.Context) {
	ctx = ctrl.LoggerInto(ctx, ctrl.Log)
	_ = ctrl.LoggerFrom(ctx)
}

func BenchmarkRaceLoggerInto(b *testing.B) {
	ctx := context.Background()
	b.RunParallel(func(pb *testing.PB) {
		for pb.Next() {
			test(ctx)
		}
	})
}

Then run it with the race detector enabled go test ./... -race -bench BenchmarkRaceLoggerInto:

▶ go test ./... -count=1 -race -bench BenchmarkRaceLoggerInto
goos: darwin
goarch: arm64
BenchmarkRaceLoggerInto-10    	 1000000	      1055 ns/op
PASS
ok  	2.901s

As you can see there is no race reported.

kevin85421

Thank @rueian @astefanutti for the explanation! It is pretty helpful!

…ay-project#1835)

rueian commented Jan 16, 2024

View reviewed changes

kevin85421 self-requested a review January 16, 2024 22:05

kevin85421 self-assigned this Jan 16, 2024

kevin85421 reviewed Jan 16, 2024

View reviewed changes

astefanutti reviewed Jan 17, 2024

View reviewed changes

rueian force-pushed the remove-logrus branch 4 times, most recently from ea122a1 to 4bbbc3a Compare January 20, 2024 06:32

rueian force-pushed the remove-logrus branch from 4bbbc3a to 01cd1d9 Compare January 23, 2024 11:38

astefanutti approved these changes Jan 25, 2024

View reviewed changes

rueian force-pushed the remove-logrus branch from 01cd1d9 to 93e8079 Compare January 25, 2024 10:41

kevin85421 reviewed Jan 25, 2024

View reviewed changes

rueian added 2 commits January 27, 2024 00:22

[Refactor] Replace logrus with logr to keep logging consistent

7a3e70b

[Refactor] Replace global logr with ctrl.LoggerFrom

3ab6e9b

rueian force-pushed the remove-logrus branch from 93e8079 to 3ab6e9b Compare January 26, 2024 16:29

kevin85421 approved these changes Jan 26, 2024

View reviewed changes

kevin85421 merged commit 19e58b2 into ray-project:master Jan 26, 2024
23 checks passed

This was referenced Feb 1, 2024

[Refactor] Remove any unnecessary logger #1894

Merged

[RayJob] Improve dashboard client log #1903

Merged

ryanaoleary pushed a commit to ryanaoleary/kuberay that referenced this pull request Feb 13, 2024

[Refactor][1/n] Replace logrus with logr to keep logging consistent (r…

ca11a86

…ay-project#1835)

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[Refactor][1/n] Replace logrus with logr to keep logging consistent #1835

[Refactor][1/n] Replace logrus with logr to keep logging consistent #1835

rueian commented Jan 16, 2024 •

edited

rueian Jan 16, 2024

rueian Jan 16, 2024

kevin85421 left a comment

kevin85421 Jan 16, 2024

rueian Jan 17, 2024

astefanutti Jan 17, 2024

rueian Jan 17, 2024

astefanutti Jan 17, 2024

astefanutti Jan 17, 2024

astefanutti Jan 17, 2024

rueian commented Jan 20, 2024

kevin85421 commented Jan 23, 2024

astefanutti left a comment

astefanutti Jan 25, 2024

rueian Jan 25, 2024

kevin85421 left a comment

astefanutti commented Jan 26, 2024

rueian commented Jan 26, 2024

kevin85421 left a comment

[Refactor][1/n] Replace logrus with logr to keep logging consistent #1835

[Refactor][1/n] Replace logrus with logr to keep logging consistent #1835

Conversation

rueian commented Jan 16, 2024 • edited

Why are these changes needed?

Related issue number

Checks

Choose a reason for hiding this comment

Choose a reason for hiding this comment

kevin85421 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

rueian commented Jan 20, 2024

kevin85421 commented Jan 23, 2024

astefanutti left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

kevin85421 left a comment

Choose a reason for hiding this comment

astefanutti commented Jan 26, 2024

rueian commented Jan 26, 2024

kevin85421 left a comment

Choose a reason for hiding this comment

rueian commented Jan 16, 2024 •

edited