[release-1.33] Migrate to contextual logging

cmd/acr-credential-provider/main.go

@@ -26,13 +26,14 @@ import (
 
 	"github.com/spf13/cobra"
 	"k8s.io/component-base/logs"
-	"k8s.io/klog/v2"
 
 	"sigs.k8s.io/cloud-provider-azure/pkg/credentialprovider"
+	"sigs.k8s.io/cloud-provider-azure/pkg/log"
 	"sigs.k8s.io/cloud-provider-azure/pkg/version"
 )
 
 func main() {
+	logger := log.Background().WithName("main")
 	rand.Seed(time.Now().UnixNano())
 
 	var RegistryMirrorStr string
@@ -45,18 +46,18 @@ func main() {
 		Version: version.Get().GitVersion,
 		Run: func(_ *cobra.Command, args []string) {
 			if len(args) != 1 {
-				klog.Errorf("Config file is not specified")
+				logger.Error(nil, "Config file is not specified")
 				os.Exit(1)
 			}
 
 			acrProvider, err := credentialprovider.NewAcrProviderFromConfig(args[0], RegistryMirrorStr)
 			if err != nil {
-				klog.Errorf("Failed to initialize ACR provider: %v", err)
+				logger.Error(err, "Failed to initialize ACR provider")
 				os.Exit(1)
 			}
 
 			if err := NewCredentialProvider(acrProvider).Run(context.TODO()); err != nil {
-				klog.Errorf("Error running acr credential provider: %v", err)
+				logger.Error(err, "Error running acr credential provider")
 				os.Exit(1)
 			}
 		},

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

@@ -72,9 +72,11 @@ const (
 
 // NewCloudControllerManagerCommand creates a *cobra.Command object with default parameters
 func NewCloudControllerManagerCommand() *cobra.Command {
+	logger := log.Background().WithName("NewCloudControllerManagerCommand")
 	s, err := options.NewCloudControllerManagerOptions()
 	if err != nil {
-		klog.Fatalf("unable to initialize command options: %v", err)
+		logger.Error(err, "unable to initialize command options")
+		klog.FlushAndExit(klog.ExitFlushTimeout, 1)
 	}
 	controllerAliases := names.CCMControllerAliases()
 
@@ -89,7 +91,7 @@ func NewCloudControllerManagerCommand() *cobra.Command {
 
 			c, err := s.Config(KnownControllers(), ControllersDisabledByDefault.List(), controllerAliases)
 			if err != nil {
-				klog.Errorf("Run: failed to configure cloud controller manager: %v", err)
+				logger.Error(err, "Run: failed to configure cloud controller manager")
 				os.Exit(1)
 			}
 
@@ -98,7 +100,7 @@ func NewCloudControllerManagerCommand() *cobra.Command {
 				var err error
 				traceProvider, err = trace.New()
 				if err != nil {
-					log.Background().Error(err, "Failed to create trace provider")
+					logger.Error(err, "Failed to create trace provider")
 					os.Exit(1)
 				}
 
@@ -107,34 +109,34 @@ func NewCloudControllerManagerCommand() *cobra.Command {
 					ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second)
 					defer cancel()
 					if err := traceProvider.Stop(ctx); err != nil {
-						log.Background().Error(err, "Failed to stop trace provider")
+						logger.Error(err, "Failed to stop trace provider")
 					}
 				}()
 
 				trace.SetGlobalProvider(traceProvider)
 
 				if err := metrics.Setup(traceProvider.DefaultMeter()); err != nil {
-					log.Background().Error(err, "Failed to setup cloud-provider metrics")
+					logger.Error(err, "Failed to setup cloud-provider metrics")
 					os.Exit(1)
 				}
 
 				if err := armmetrics.Setup(traceProvider.DefaultMeter()); err != nil {
-					log.Background().Error(err, "Failed to setup ARM SDK metrics")
+					logger.Error(err, "Failed to setup ARM SDK metrics")
 					os.Exit(1)
 				}
 			}
 
 			healthHandler, err := StartHTTPServer(cmd.Context(), c.Complete(), traceProvider)
 			if err != nil {
-				klog.Errorf("Run: railed to start HTTP server: %v", err)
+				logger.Error(err, "Run: failed to start HTTP server")
 				os.Exit(1)
 			}
 
 			if c.ComponentConfig.Generic.LeaderElection.LeaderElect {
 				// Identity used to distinguish between multiple cloud controller manager instances
 				id, err := os.Hostname()
 				if err != nil {
-					klog.Errorf("Run: failed to get host name: %v", err)
+					logger.Error(err, "Run: failed to get host name")
 					os.Exit(1)
 				}
 				// add a uniquifier so that two processes on the same host don't accidentally both become active
@@ -151,7 +153,8 @@ func NewCloudControllerManagerCommand() *cobra.Command {
 					c.Kubeconfig,
 					c.ComponentConfig.Generic.LeaderElection.RenewDeadline.Duration)
 				if err != nil {
-					klog.Fatalf("error creating lock: %v", err)
+					logger.Error(err, "error creating lock")
+					klog.FlushAndExit(klog.ExitFlushTimeout, 1)
 				}
 
 				// Try and become the leader and start cloud controller manager loops
@@ -168,7 +171,7 @@ func NewCloudControllerManagerCommand() *cobra.Command {
 					Callbacks: leaderelection.LeaderCallbacks{
 						OnStartedLeading: RunWrapper(s, c, healthHandler),
 						OnStoppedLeading: func() {
-							klog.ErrorS(nil, "leaderelection lost")
+							logger.Error(nil, "leaderelection lost")
 							klog.FlushAndExit(klog.ExitFlushTimeout, 1)
 						},
 					},
@@ -212,21 +215,22 @@ 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) {
 	return func(ctx context.Context) {
+		logger := log.FromContextOrBackground(ctx).WithName("RunWrapper")
 		if !c.DynamicReloadingConfig.EnableDynamicReloading {
-			klog.V(1).Infof("using static initialization from config file %s", c.ComponentConfig.KubeCloudShared.CloudProvider.CloudConfigFile)
+			logger.V(1).Info("using static initialization from config file", "cloudConfigFile", c.ComponentConfig.KubeCloudShared.CloudProvider.CloudConfigFile)
 			if err := Run(ctx, c.Complete(), h); err != nil {
-				klog.Errorf("RunWrapper: failed to start cloud controller manager: %v", err)
+				logger.Error(err, "RunWrapper: failed to start cloud controller manager")
 				os.Exit(1)
 			}
 		}
 		var updateCh chan struct{}
 
 		cloudConfigFile := c.ComponentConfig.KubeCloudShared.CloudProvider.CloudConfigFile
 		if cloudConfigFile != "" {
-			klog.V(1).Infof("RunWrapper: using dynamic initialization from config file %s, starting the file watcher", cloudConfigFile)
+			logger.V(1).Info("using dynamic initialization from config file, starting the file watcher", "cloudConfigFile", cloudConfigFile)
 			updateCh = dynamic.RunFileWatcherOrDie(cloudConfigFile)
 		} else {
-			klog.V(1).Infof("RunWrapper: using dynamic initialization from secret %s/%s, starting the secret watcher", c.DynamicReloadingConfig.CloudConfigSecretNamespace, c.DynamicReloadingConfig.CloudConfigSecretName)
+			logger.V(1).Info("using dynamic initialization from secret, starting the secret watcher", "namespace", c.DynamicReloadingConfig.CloudConfigSecretNamespace, "name", c.DynamicReloadingConfig.CloudConfigSecretName)
 			updateCh = dynamic.RunSecretWatcherOrDie(c)
 		}
 
@@ -235,7 +239,7 @@ func RunWrapper(s *options.CloudControllerManagerOptions, c *cloudcontrollerconf
 		for {
 			select {
 			case <-updateCh:
-				klog.V(2).Info("RunWrapper: detected the cloud config has been updated, re-constructing the cloud controller manager")
+				logger.V(2).Info("detected the cloud config has been updated, re-constructing the cloud controller manager")
 
 				// stop the previous goroutines
 				cancelFunc()
@@ -248,60 +252,63 @@ func RunWrapper(s *options.CloudControllerManagerOptions, c *cloudcontrollerconf
 					// start new goroutines if needed when using config file
 					shouldRemainStopped, err = shouldDisableCloudProvider(cloudConfigFile)
 					if err != nil {
-						klog.Fatalf("RunWrapper: failed to determine if it is needed to restart all controllers: %s", err.Error())
+						logger.Error(err, "failed to determine if it is needed to restart all controllers")
+						klog.FlushAndExit(klog.ExitFlushTimeout, 1)
 					}
 				}
 
 				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!")
 				}
 
 			case err := <-errCh:
-				klog.Errorf("RunWrapper: failed to start cloud controller manager: %v", err)
+				logger.Error(err, "RunWrapper: failed to start cloud controller manager")
 				os.Exit(1)
 			}
 		}
 	}
 }
 
 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())
+		logger.Error(err, "shouldDisableCloudProvider: failed to read", "configFilePath", configFilePath)
 		return false, err
 	}
 
 	var c struct {
 		DisableCloudProvider bool `json:"disableCloudProvider,omitempty"`
 	}
 	if err = json.Unmarshal(configBytes, &c); err != nil {
-		klog.Errorf("shouldDisableCloudProvider: failed to unmarshal configBytes to struct: %s", err.Error())
+		logger.Error(err, "shouldDisableCloudProvider: failed to unmarshal configBytes to struct")
 		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
 }
 
 func runAsync(s *options.CloudControllerManagerOptions, errCh chan error, h *controllerhealthz.MutableHealthzHandler) context.CancelFunc {
 	ctx, cancelFunc := context.WithCancel(context.Background())
+	logger := log.FromContextOrBackground(ctx).WithName("runAsync")
 
 	go func() {
 		c, err := s.Config(KnownControllers(), ControllersDisabledByDefault.List(), names.CCMControllerAliases())
 		if err != nil {
-			klog.Errorf("RunAsync: failed to configure cloud controller manager: %v", err)
+			logger.Error(err, "RunAsync: failed to configure cloud controller manager")
 			os.Exit(1)
 		}
 
 		if err := Run(ctx, c.Complete(), h); err != nil {
-			klog.Errorf("RunAsync: failed to run cloud controller manager: %v", err)
+			logger.Error(err, "RunAsync: failed to run cloud controller manager")
 			errCh <- err
 		}
 
-		klog.V(1).Infof("RunAsync: stopping")
+		logger.V(1).Info("stopping")
 	}()
 
 	return cancelFunc
@@ -341,8 +348,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.FromContextOrBackground(ctx).WithName("Run")
 	// To help debugging, immediately log version
-	klog.Infof("Version: %#v", version.Get())
+	logger.Info("Version", "version", version.Get())
 
 	var (
 		cloud cloudprovider.Interface
@@ -352,43 +360,49 @@ func Run(ctx context.Context, c *cloudcontrollerconfig.CompletedConfig, h *contr
 	if c.ComponentConfig.KubeCloudShared.CloudProvider.CloudConfigFile != "" {
 		cloud, err = provider.NewCloudFromConfigFile(ctx, c.ClientBuilder, c.ComponentConfig.KubeCloudShared.CloudProvider.CloudConfigFile, true)
 		if err != nil {
-			klog.Fatalf("Cloud provider azure could not be initialized: %v", err)
+			logger.Error(err, "Cloud provider azure could not be initialized")
+			klog.FlushAndExit(klog.ExitFlushTimeout, 1)
 		}
 	} else if c.DynamicReloadingConfig.EnableDynamicReloading && c.DynamicReloadingConfig.CloudConfigSecretName != "" {
 		cloud, err = provider.NewCloudFromSecret(ctx, c.ClientBuilder, c.DynamicReloadingConfig.CloudConfigSecretName, c.DynamicReloadingConfig.CloudConfigSecretNamespace, c.DynamicReloadingConfig.CloudConfigKey)
 		if err != nil {
-			klog.Fatalf("Run: Cloud provider azure could not be initialized dynamically from secret %s/%s: %v", c.DynamicReloadingConfig.CloudConfigSecretNamespace, c.DynamicReloadingConfig.CloudConfigSecretName, err)
+			logger.Error(err, "Cloud provider azure could not be initialized dynamically from secret", "namespace", c.DynamicReloadingConfig.CloudConfigSecretNamespace, "name", c.DynamicReloadingConfig.CloudConfigSecretName)
+			klog.FlushAndExit(klog.ExitFlushTimeout, 1)
 		}
 	}
 
 	if cloud == nil {
-		klog.Fatalf("cloud provider is nil, please check if the --cloud-config is set properly")
+		logger.Error(nil, "cloud provider is nil, please check if the --cloud-config is set properly")
+		klog.FlushAndExit(klog.ExitFlushTimeout, 1)
 	}
 
 	if !cloud.HasClusterID() {
 		if c.ComponentConfig.KubeCloudShared.AllowUntaggedCloud {
 			klog.Warning("detected a cluster without a ClusterID.  A ClusterID will be required in the future.  Please tag your cluster to avoid any future issues")
 		} else {
-			klog.Fatalf("no ClusterID found.  A ClusterID is required for the cloud provider to function properly.  This check can be bypassed by setting the allow-untagged-cloud option")
+			logger.Error(nil, "no ClusterID found.  A ClusterID is required for the cloud provider to function properly.  This check can be bypassed by setting the allow-untagged-cloud option")
+			klog.FlushAndExit(klog.ExitFlushTimeout, 1)
 		}
 	}
 
 	// setup /configz endpoint
 	if cz, err := configz.New(ConfigzName); err == nil {
 		cz.Set(c.ComponentConfig)
 	} else {
-		klog.Errorf("unable to register configz: %v", err)
+		logger.Error(err, "unable to register configz")
 	}
 	clientBuilder := clientbuilder.SimpleControllerClientBuilder{
 		ClientConfig: c.Kubeconfig,
 	}
 	controllerContext, err := CreateControllerContext(c, clientBuilder, ctx.Done())
 	if err != nil {
-		klog.Fatalf("error building controller context: %v", err)
+		logger.Error(err, "error building controller context")
+		klog.FlushAndExit(klog.ExitFlushTimeout, 1)
 	}
 
 	if err := startControllers(ctx, controllerContext, c, cloud, newControllerInitializers(), h); err != nil {
-		klog.Fatalf("error running controllers: %v", err)
+		logger.Error(err, "error running controllers")
+		klog.FlushAndExit(klog.ExitFlushTimeout, 1)
 	}
 
 	return nil
@@ -397,6 +411,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.FromContextOrBackground(ctx).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
@@ -411,10 +426,10 @@ func startControllers(ctx context.Context, controllerContext genericcontrollerma
 			continue
 		}
 
-		klog.V(1).Infof("Starting %q", controllerName)
+		logger.V(1).Info("Starting controller", "controller", controllerName)
 		ctrl, started, err := initFn(ctx, controllerContext, completedConfig, cloud)
 		if err != nil {
-			klog.Errorf("Error starting %q: %s", controllerName, err.Error())
+			logger.Error(err, "Error starting", "controller", controllerName)
 			return err
 		}
 		if !started {
@@ -430,7 +445,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))
 	}
@@ -441,14 +456,15 @@ func startControllers(ctx context.Context, controllerContext genericcontrollerma
 	// If apiserver is not running we should wait for some time and fail only then. This is particularly
 	// important when we start apiserver and controller manager at the same time.
 	if err := genericcontrollermanager.WaitForAPIServer(completedConfig.VersionedClient, 10*time.Second); err != nil {
-		klog.Fatalf("Failed to wait for apiserver being healthy: %v", err)
+		logger.Error(err, "Failed to wait for apiserver being healthy")
+		klog.FlushAndExit(klog.ExitFlushTimeout, 1)
 	}
 
-	klog.V(2).Infof("startControllers: starting shared informers")
+	logger.V(2).Info("startControllers: starting shared informers")
 	completedConfig.SharedInformers.Start(ctx.Done())
 	controllerContext.InformerFactory.Start(ctx.Done())
 	<-ctx.Done()
-	klog.V(1).Infof("startControllers: received stopping signal, exiting")
+	logger.V(1).Info("startControllers: received stopping signal, exiting")
 
 	return nil
 }

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"
@@ -83,6 +84,7 @@ func startCloudNodeLifecycleController(ctx context.Context, controllerContext ge
 }
 
 func startServiceController(ctx context.Context, controllerContext genericcontrollermanager.ControllerContext, completedConfig *cloudcontrollerconfig.CompletedConfig, cloud cloudprovider.Interface) (http.Handler, bool, error) {
+	logger := log.FromContextOrBackground(ctx).WithName("startServiceController")
 	// Start the service controller
 	serviceController, err := servicecontroller.New(
 		cloud,
@@ -94,7 +96,7 @@ func startServiceController(ctx context.Context, controllerContext genericcontro
 	)
 	if err != nil {
 		// This error shouldn't fail. It lives like this as a legacy.
-		klog.Errorf("Failed to start service controller: %v", err)
+		logger.Error(err, "Failed to start service controller")
 		return nil, false, nil
 	}
 
@@ -104,8 +106,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.FromContextOrBackground(ctx).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
 	}