Use contextual logger in base controller (#165)

Signed-off-by: Jian Qiu <jqiu@redhat.com>

Author: qiujian16

pkg/basecontroller/factory/base_controller.go

@@ -30,14 +30,16 @@ func (c baseController) Name() string {
 	return c.name
 }
 
-func waitForNamedCacheSync(controllerName string, stopCh <-chan struct{}, cacheSyncs ...cache.InformerSynced) error {
-	klog.Infof("Waiting for caches to sync for %s", controllerName)
+func waitForNamedCacheSync(ctx context.Context, controllerName string, stopCh <-chan struct{}, cacheSyncs ...cache.InformerSynced) error {
+	logger := klog.FromContext(ctx)
+
+	logger.Info("Waiting for caches to sync")
 
 	if !cache.WaitForCacheSync(stopCh, cacheSyncs...) {
 		return fmt.Errorf("unable to sync caches for %s", controllerName)
 	}
 
-	klog.Infof("Caches are synced for %s ", controllerName)
+	logger.Info("Caches are synced")
 
 	return nil
 }
@@ -47,10 +49,13 @@ func (c *baseController) SyncContext() SyncContext {
 }
 
 func (c *baseController) Run(ctx context.Context, workers int) {
+	logger := klog.FromContext(ctx).WithName(c.name)
+	ctx = klog.NewContext(ctx, logger)
+
 	// give caches 10 minutes to sync
 	cacheSyncCtx, cacheSyncCancel := context.WithTimeout(ctx, c.cacheSyncTimeout)
 	defer cacheSyncCancel()
-	err := waitForNamedCacheSync(c.name, cacheSyncCtx.Done(), c.cachesToSync...)
+	err := waitForNamedCacheSync(ctx, c.name, cacheSyncCtx.Done(), c.cachesToSync...)
 	if err != nil {
 		select {
 		case <-ctx.Done():
@@ -67,19 +72,19 @@ func (c *baseController) Run(ctx context.Context, workers int) {
 
 	var workerWg sync.WaitGroup
 	defer func() {
-		defer klog.Infof("All %s workers have been terminated", c.name)
+		defer logger.Info("All workers have been terminated")
 		workerWg.Wait()
 	}()
 
 	// queueContext is used to track and initiate queue shutdown
-	queueContext, queueContextCancel := context.WithCancel(context.TODO())
+	queueContext, queueContextCancel := context.WithCancel(ctx)
 
 	for i := 1; i <= workers; i++ {
-		klog.Infof("Starting #%d worker of %s controller ...", i, c.name)
+		logger.Info("Starting worker of controller ...", "numberOfWorkers", i)
 		workerWg.Add(1)
 		go func() {
 			defer func() {
-				klog.Infof("Shutting down worker of %s controller ...", c.name)
+				logger.Info("Shutting down worker of controller ...")
 				workerWg.Done()
 			}()
 			c.runWorker(queueContext)
@@ -104,7 +109,7 @@ func (c *baseController) Run(ctx context.Context, workers int) {
 	// Wait for all workers to finish their job.
 	// at this point the Run() can hang and caller have to implement the logic that will kill
 	// this controller (SIGKILL).
-	klog.Infof("Shutting down %s ...", c.name)
+	logger.Info("Shutting down ...")
 }
 
 func (c *baseController) Sync(ctx context.Context, syncCtx SyncContext, key string) error {
@@ -140,6 +145,8 @@ func (c *baseController) runWorker(queueCtx context.Context) {
 }
 
 func (c *baseController) processNextWorkItem(queueCtx context.Context) {
+	logger := klog.FromContext(queueCtx)
+
 	key, quit := c.syncContext.Queue().Get()
 	if quit {
 		return
@@ -150,10 +157,10 @@ func (c *baseController) processNextWorkItem(queueCtx context.Context) {
 	queueKey := key
 
 	if err := c.sync(queueCtx, syncCtx, queueKey); err != nil {
-		if klog.V(4).Enabled() || key != "key" {
-			utilruntime.HandleError(fmt.Errorf("%q controller failed to sync %q, err: %w", c.name, key, err))
+		if logger.V(4).Enabled() || key != "key" {
+			utilruntime.HandleErrorWithContext(queueCtx, err, "controller failed to sync", "key", key, "error", err)
 		} else {
-			utilruntime.HandleError(fmt.Errorf("%s reconciliation failed: %w", c.name, err))
+			utilruntime.HandleErrorWithContext(queueCtx, err, "reconciliation failed", "error", err)
 		}
 		c.syncContext.Queue().AddRateLimited(key)
 		return