Migrate info logging to contextual logging

Author: anndono

cmd/cloud-controller-manager/app/controllermanager.go

@@ -211,6 +211,7 @@ func NewCloudControllerManagerCommand() *cobra.Command {
 
 // RunWrapper adapts the ccm boot logic to the leader elector call back function
 func RunWrapper(s *options.CloudControllerManagerOptions, c *cloudcontrollerconfig.Config, h *controllerhealthz.MutableHealthzHandler) func(ctx context.Context) {
+	logger := log.Background().WithName("RunWrapper")
 	return func(ctx context.Context) {
 		if !c.DynamicReloadingConfig.EnableDynamicReloading {
 			klog.V(1).Infof("using static initialization from config file %s", c.ComponentConfig.KubeCloudShared.CloudProvider.CloudConfigFile)
@@ -253,7 +254,7 @@ func RunWrapper(s *options.CloudControllerManagerOptions, c *cloudcontrollerconf
 				}
 
 				if !shouldRemainStopped {
-					klog.Info("RunWrapper: restarting all controllers")
+					logger.Info("RunWrapper: restarting all controllers")
 					cancelFunc = runAsync(s, errCh, h)
 				} else {
 					klog.Warningf("All controllers are stopped!")
@@ -268,6 +269,7 @@ func RunWrapper(s *options.CloudControllerManagerOptions, c *cloudcontrollerconf
 }
 
 func shouldDisableCloudProvider(configFilePath string) (bool, error) {
+	logger := log.Background().WithName("shouldDisableCloudProvider")
 	configBytes, err := os.ReadFile(configFilePath)
 	if err != nil {
 		klog.Errorf("shouldDisableCloudProvider: failed to read %s  %s", configFilePath, err.Error())
@@ -282,7 +284,7 @@ func shouldDisableCloudProvider(configFilePath string) (bool, error) {
 		return false, err
 	}
 
-	klog.Infof("shouldDisableCloudProvider: should disable cloud provider: %t", c.DisableCloudProvider)
+	logger.Info("should disable cloud provider", "disableCloudProvider", c.DisableCloudProvider)
 	return c.DisableCloudProvider, nil
 }
 
@@ -341,8 +343,9 @@ func StartHTTPServer(ctx context.Context, c *cloudcontrollerconfig.CompletedConf
 
 // Run runs the ExternalCMServer.  This should never exit.
 func Run(ctx context.Context, c *cloudcontrollerconfig.CompletedConfig, h *controllerhealthz.MutableHealthzHandler) error {
+	logger := log.Background().WithName("Run")
 	// To help debugging, immediately log version
-	klog.Infof("Version: %#v", version.Get())
+	logger.Info("Version", "version", version.Get())
 
 	var (
 		cloud cloudprovider.Interface
@@ -397,6 +400,7 @@ func Run(ctx context.Context, c *cloudcontrollerconfig.CompletedConfig, h *contr
 // startControllers starts the cloud specific controller loops.
 func startControllers(ctx context.Context, controllerContext genericcontrollermanager.ControllerContext, completedConfig *cloudcontrollerconfig.CompletedConfig,
 	cloud cloudprovider.Interface, controllers map[string]initFunc, healthzHandler *controllerhealthz.MutableHealthzHandler) error {
+	logger := log.Background().WithName("startControllers")
 	// Initialize the cloud provider with a reference to the clientBuilder
 	cloud.Initialize(completedConfig.ClientBuilder, ctx.Done())
 	// Set the informer on the user cloud object
@@ -430,7 +434,7 @@ func startControllers(ctx context.Context, controllerContext genericcontrollerma
 			}
 		}
 		controllerChecks = append(controllerChecks, check)
-		klog.Infof("Started %q", controllerName)
+		logger.Info("Started", "controller", controllerName)
 
 		time.Sleep(wait.Jitter(completedConfig.ComponentConfig.Generic.ControllerStartInterval.Duration, ControllerStartJitter))
 	}

cmd/cloud-controller-manager/app/core.go

@@ -38,6 +38,7 @@ import (
 
 	cloudcontrollerconfig "sigs.k8s.io/cloud-provider-azure/cmd/cloud-controller-manager/app/config"
 	"sigs.k8s.io/cloud-provider-azure/pkg/consts"
+	"sigs.k8s.io/cloud-provider-azure/pkg/log"
 	nodeipamcontroller "sigs.k8s.io/cloud-provider-azure/pkg/nodeipam"
 	nodeipamconfig "sigs.k8s.io/cloud-provider-azure/pkg/nodeipam/config"
 	"sigs.k8s.io/cloud-provider-azure/pkg/nodeipam/ipam"
@@ -104,8 +105,9 @@ func startServiceController(ctx context.Context, controllerContext genericcontro
 }
 
 func startRouteController(ctx context.Context, controllerContext genericcontrollermanager.ControllerContext, completedConfig *cloudcontrollerconfig.CompletedConfig, cloud cloudprovider.Interface) (http.Handler, bool, error) {
+	logger := log.Background().WithName("startRouteController")
 	if !completedConfig.ComponentConfig.KubeCloudShared.ConfigureCloudRoutes {
-		klog.Infof("Will not configure cloud provider routes, --configure-cloud-routes: %v.", completedConfig.ComponentConfig.KubeCloudShared.ConfigureCloudRoutes)
+		logger.Info("Will not configure cloud provider routes", "--configure-cloud-routes", completedConfig.ComponentConfig.KubeCloudShared.ConfigureCloudRoutes)
 		return nil, false, nil
 	}
 

cmd/cloud-controller-manager/app/dynamic/file_watcher.go

@@ -24,9 +24,11 @@ import (
 	"github.com/fsnotify/fsnotify"
 
 	"k8s.io/klog/v2"
+	"sigs.k8s.io/cloud-provider-azure/pkg/log"
 )
 
 func RunFileWatcherOrDie(path string) chan struct{} {
+	logger := log.Background().WithName("RunFileWatcherOrDie")
 	watcher, err := fsnotify.NewWatcher()
 	if err != nil {
 		klog.Errorf("RunFileWatcherOrDie: failed to initialize file watcher: %s", err)
@@ -46,7 +48,7 @@ func RunFileWatcherOrDie(path string) chan struct{} {
 					os.Exit(1)
 				}
 
-				klog.Infof("RunFileWatcherOrDie: found file update event: %v", event)
+				logger.Info("found file update event", "event", event)
 				updateChan <- struct{}{}
 
 				if strings.EqualFold(event.Name, path) && event.Op&fsnotify.Remove == fsnotify.Remove {

cmd/cloud-node-manager/app/nodemanager.go

@@ -34,6 +34,7 @@ import (
 
 	cloudnodeconfig "sigs.k8s.io/cloud-provider-azure/cmd/cloud-node-manager/app/config"
 	"sigs.k8s.io/cloud-provider-azure/cmd/cloud-node-manager/app/options"
+	"sigs.k8s.io/cloud-provider-azure/pkg/log"
 	nodeprovider "sigs.k8s.io/cloud-provider-azure/pkg/node"
 	"sigs.k8s.io/cloud-provider-azure/pkg/nodemanager"
 	"sigs.k8s.io/cloud-provider-azure/pkg/version"
@@ -94,9 +95,10 @@ func NewCloudNodeManagerCommand() *cobra.Command {
 
 // Run runs the ExternalCMServer.  This should never exit.
 func Run(ctx context.Context, c *cloudnodeconfig.Config) error {
+	logger := log.Background().WithName("Run")
 	// To help debugging, immediately log version and nodeName
-	klog.Infof("Version: %+v", version.Get())
-	klog.Infof("NodeName: %s", c.NodeName)
+	logger.Info("Version", "version", version.Get())
+	logger.Info("NodeName", "nodeName", c.NodeName)
 
 	// Start the controller manager HTTP server
 	var checks []healthz.HealthChecker
@@ -122,6 +124,7 @@ func Run(ctx context.Context, c *cloudnodeconfig.Config) error {
 
 // startControllers starts the cloud specific controller loops.
 func startControllers(ctx context.Context, c *cloudnodeconfig.Config, healthzHandler *controllerhealthz.MutableHealthzHandler) error {
+	logger := log.Background().WithName("startControllers")
 	klog.V(1).Infof("Starting cloud-node-manager...")
 
 	// Start the CloudNodeController
@@ -140,7 +143,7 @@ func startControllers(ctx context.Context, c *cloudnodeconfig.Config, healthzHan
 	check := controllerhealthz.NamedPingChecker(c.NodeName)
 	healthzHandler.AddHealthChecker(check)
 
-	klog.Infof("Started cloud-node-manager")
+	logger.Info("Started cloud-node-manager")
 
 	// If apiserver is not running we should wait for some time and fail only then. This is particularly
 	// important when we start node manager before apiserver starts.

pkg/nodeipam/ipam/cloud_cidr_allocator.go

@@ -39,6 +39,7 @@ import (
 	netutils "k8s.io/utils/net"
 
 	"sigs.k8s.io/cloud-provider-azure/pkg/consts"
+	"sigs.k8s.io/cloud-provider-azure/pkg/log"
 	"sigs.k8s.io/cloud-provider-azure/pkg/nodeipam/ipam/cidrset"
 	providerazure "sigs.k8s.io/cloud-provider-azure/pkg/provider"
 	nodeutil "sigs.k8s.io/cloud-provider-azure/pkg/util/controller/node"
@@ -264,10 +265,11 @@ func (ca *cloudCIDRAllocator) updateNodeSubnetMaskSizes(ctx context.Context, nod
 }
 
 func (ca *cloudCIDRAllocator) Run(ctx context.Context) {
+	logger := log.Background().WithName("Run")
 	defer utilruntime.HandleCrash()
 
-	klog.Infof("Starting cloud CIDR allocator")
-	defer klog.Infof("Shutting down cloud CIDR allocator")
+	logger.Info("Starting cloud CIDR allocator")
+	defer logger.Info("Shutting down cloud CIDR allocator")
 
 	if !cache.WaitForNamedCacheSync("cidrallocator", ctx.Done(), ca.nodesSynced) {
 		return

pkg/nodeipam/node_ipam_controller.go

@@ -35,6 +35,7 @@ import (
 	"k8s.io/component-base/metrics/legacyregistry"
 	"k8s.io/klog/v2"
 
+	"sigs.k8s.io/cloud-provider-azure/pkg/log"
 	"sigs.k8s.io/cloud-provider-azure/pkg/nodeipam/ipam"
 )
 
@@ -119,14 +120,15 @@ func NewNodeIpamController(
 	nodeCIDRMaskSizes []int,
 	allocatorType ipam.CIDRAllocatorType) (*Controller, error) {
 
+	logger := log.Background().WithName("NewNodeIpamController")
 	if kubeClient == nil {
 		klog.Fatalf("kubeClient is nil when starting Controller")
 	}
 
 	eventBroadcaster := record.NewBroadcaster()
 	eventBroadcaster.StartStructuredLogging(0)
 
-	klog.Infof("Sending events to api server.")
+	logger.Info("Sending events to api server")
 	eventBroadcaster.StartRecordingToSink(
 		&v1core.EventSinkImpl{
 			Interface: kubeClient.CoreV1().Events(""),
@@ -188,10 +190,11 @@ func NewNodeIpamController(
 
 // Run starts an asynchronous loop that monitors the status of cluster nodes.
 func (nc *Controller) Run(ctx context.Context) {
+	logger := log.Background().WithName("Run")
 	defer utilruntime.HandleCrash()
 
-	klog.Infof("Starting ipam controller")
-	defer klog.Infof("Shutting down ipam controller")
+	logger.Info("Starting ipam controller")
+	defer logger.Info("Shutting down ipam controller")
 
 	if !cache.WaitForNamedCacheSync("node", ctx.Done(), nc.nodeInformerSynced) {
 		return

pkg/nodemanager/nodemanager.go

@@ -47,6 +47,7 @@ import (
 	"k8s.io/klog/v2"
 
 	"sigs.k8s.io/cloud-provider-azure/pkg/consts"
+	"sigs.k8s.io/cloud-provider-azure/pkg/log"
 )
 
 // NodeProvider defines the interfaces for node provider.
@@ -367,7 +368,8 @@ func (cnc *CloudNodeController) AddCloudNode(ctx context.Context, obj interface{
 
 // This processes nodes that were added into the cluster, and cloud initialize them if appropriate
 func (cnc *CloudNodeController) initializeNode(ctx context.Context, node *v1.Node) {
-	klog.Infof("Initializing node %s with cloud provider", node.Name)
+	logger := log.Background().WithName("initializeNode")
+	logger.Info("Initializing node with cloud provider", "node", node.Name)
 	curNode, err := cnc.kubeClient.CoreV1().Nodes().Get(ctx, node.Name, metav1.GetOptions{})
 	if err != nil {
 		utilruntime.HandleError(fmt.Errorf("failed to get node %s: %w", node.Name, err))
@@ -430,7 +432,7 @@ func (cnc *CloudNodeController) initializeNode(ctx context.Context, node *v1.Nod
 			return err
 		}
 
-		klog.Infof("Successfully initialized node %s with cloud provider", node.Name)
+		logger.Info("Successfully initialized node with cloud provider", "node", node.Name)
 		return nil
 	})
 	if err != nil {

pkg/provider/azure.go

@@ -44,6 +44,7 @@ import (
 	"sigs.k8s.io/cloud-provider-azure/pkg/azclient/configloader"
 	azcache "sigs.k8s.io/cloud-provider-azure/pkg/cache"
 	"sigs.k8s.io/cloud-provider-azure/pkg/consts"
+	"sigs.k8s.io/cloud-provider-azure/pkg/log"
 	azureconfig "sigs.k8s.io/cloud-provider-azure/pkg/provider/config"
 	"sigs.k8s.io/cloud-provider-azure/pkg/provider/privatelinkservice"
 	"sigs.k8s.io/cloud-provider-azure/pkg/provider/routetable"
@@ -254,6 +255,7 @@ var (
 
 // InitializeCloudFromConfig initializes the Cloud from config.
 func (az *Cloud) InitializeCloudFromConfig(ctx context.Context, config *azureconfig.Config, _, callFromCCM bool) error {
+	logger := log.Background().WithName("InitializeCloudFromConfig")
 	if config == nil {
 		// should not reach here
 		return fmt.Errorf("InitializeCloudFromConfig: cannot initialize from nil config")
@@ -418,15 +420,15 @@ func (az *Cloud) InitializeCloudFromConfig(ctx context.Context, config *azurecon
 		if err != nil {
 			return err
 		}
-		klog.InfoS("Setting up ARM client factory for network resources", "subscriptionID", networkSubscriptionID)
+		logger.Info("Setting up ARM client factory for network resources", "subscriptionID", networkSubscriptionID)
 
 		az.ComputeClientFactory, err = newARMClientFactory(&azclient.ClientFactoryConfig{
 			SubscriptionID: az.SubscriptionID,
 		}, &az.ARMClientConfig, clientOps.Cloud, computeCred, az.AuthProvider.AdditionalComputeClientOptions...)
 		if err != nil {
 			return err
 		}
-		klog.InfoS("Setting up ARM client factory for compute resources", "subscriptionID", az.SubscriptionID)
+		logger.Info("Setting up ARM client factory for compute resources", "subscriptionID", az.SubscriptionID)
 	}
 
 	networkClientFactory := az.NetworkClientFactory
@@ -538,8 +540,9 @@ func (az *Cloud) checkEnableMultipleStandardLoadBalancers() error {
 }
 
 func (az *Cloud) initCaches() (err error) {
+	logger := log.Background().WithName("initCaches")
 	if az.DisableAPICallCache {
-		klog.Infof("API call cache is disabled, ignore logs about cache operations")
+		logger.Info("API call cache is disabled, ignore logs about cache operations")
 	}
 
 	az.vmCache, err = az.newVMCache()
@@ -683,7 +686,8 @@ func (az *Cloud) ProviderName() string {
 
 // SetInformers sets informers for Azure cloud provider.
 func (az *Cloud) SetInformers(informerFactory informers.SharedInformerFactory) {
-	klog.Infof("Setting up informers for Azure cloud provider")
+	logger := log.Background().WithName("SetInformers")
+	logger.Info("Setting up informers for Azure cloud provider")
 	nodeInformer := informerFactory.Core().V1().Nodes().Informer()
 	_, _ = nodeInformer.AddEventHandler(cache.ResourceEventHandlerFuncs{
 		AddFunc: func(obj interface{}) {
@@ -729,6 +733,7 @@ func (az *Cloud) SetInformers(informerFactory informers.SharedInformerFactory) {
 
 // updateNodeCaches updates local cache for node's zones and external resource groups.
 func (az *Cloud) updateNodeCaches(prevNode, newNode *v1.Node) {
+	logger := log.Background().WithName("updateNodeCaches")
 	az.nodeCachesLock.Lock()
 	defer az.nodeCachesLock.Unlock()
 
@@ -754,8 +759,7 @@ func (az *Cloud) updateNodeCaches(prevNode, newNode *v1.Node) {
 		managed, ok := prevNode.Labels[consts.ManagedByAzureLabel]
 		isNodeManagedByCloudProvider := !ok || !strings.EqualFold(managed, consts.NotManagedByAzureLabelValue)
 
-		klog.Infof("managed=%v, ok=%v, isNodeManagedByCloudProvider=%v",
-			managed, ok, isNodeManagedByCloudProvider)
+		logger.Info("node management status", "managed", managed, "ok", ok, "isNodeManagedByCloudProvider", isNodeManagedByCloudProvider)
 
 		// Remove from unmanagedNodes cache
 		if !isNodeManagedByCloudProvider {

pkg/provider/azure_local_services.go

@@ -35,6 +35,7 @@ import (
 	"k8s.io/utils/ptr"
 
 	"sigs.k8s.io/cloud-provider-azure/pkg/consts"
+	"sigs.k8s.io/cloud-provider-azure/pkg/log"
 	"sigs.k8s.io/cloud-provider-azure/pkg/metrics"
 	"sigs.k8s.io/cloud-provider-azure/pkg/util/errutils"
 	utilsets "sigs.k8s.io/cloud-provider-azure/pkg/util/sets"
@@ -89,12 +90,13 @@ func newLoadBalancerBackendPoolUpdater(az *Cloud, interval time.Duration) *loadB
 
 // run starts the loadBalancerBackendPoolUpdater, and stops if the context exits.
 func (updater *loadBalancerBackendPoolUpdater) run(ctx context.Context) {
+	logger := log.Background().WithName("run")
 	klog.V(2).Info("loadBalancerBackendPoolUpdater.run: started")
 	err := wait.PollUntilContextCancel(ctx, updater.interval, false, func(ctx context.Context) (bool, error) {
 		updater.process(ctx)
 		return false, nil
 	})
-	klog.Infof("loadBalancerBackendPoolUpdater.run: stopped due to %s", err.Error())
+	logger.Error(err, "loadBalancerBackendPoolUpdater.run: stopped")
 }
 
 // getAddIPsToBackendPoolOperation creates a new loadBalancerBackendPoolUpdateOperation

pkg/provider/azure_routes.go

@@ -33,6 +33,7 @@ import (
 
 	azcache "sigs.k8s.io/cloud-provider-azure/pkg/cache"
 	"sigs.k8s.io/cloud-provider-azure/pkg/consts"
+	"sigs.k8s.io/cloud-provider-azure/pkg/log"
 	"sigs.k8s.io/cloud-provider-azure/pkg/metrics"
 )
 
@@ -88,12 +89,13 @@ func newDelayedRouteUpdater(az *Cloud, interval time.Duration) batchProcessor {
 
 // run starts the updater reconciling loop.
 func (d *delayedRouteUpdater) run(ctx context.Context) {
-	klog.Info("delayedRouteUpdater: started")
+	logger := log.Background().WithName("delayedRouteUpdater")
+	logger.Info("delayedRouteUpdater: started")
 	err := wait.PollUntilContextCancel(ctx, d.interval, true, func(ctx context.Context) (bool, error) {
 		d.updateRoutes(ctx)
 		return false, nil
 	})
-	klog.Infof("delayedRouteUpdater: stopped due to %s", err.Error())
+	logger.Error(err, "delayedRouteUpdater: stopped")
 }
 
 // updateRoutes invokes route table client to update all routes.