Merge pull request #113464 from mengjiao-liu/contextual-logging-controller-bootstrap

Migrate `pkg/controller/bootstrap` to contextual logging

cmd/kube-controller-manager/app/bootstrap.go

@@ -20,11 +20,14 @@ import (
 	"context"
 	"fmt"
 
+	"k8s.io/klog/v2"
+
 	"k8s.io/controller-manager/controller"
 	"k8s.io/kubernetes/pkg/controller/bootstrap"
 )
 
 func startBootstrapSignerController(ctx context.Context, controllerContext ControllerContext) (controller.Interface, bool, error) {
+	ctx = klog.NewContext(ctx, klog.LoggerWithName(klog.FromContext(ctx), "bootstrap-signer-controller"))
 	bsc, err := bootstrap.NewSigner(
 		controllerContext.ClientBuilder.ClientOrDie("bootstrap-signer"),
 		controllerContext.InformerFactory.Core().V1().Secrets(),
@@ -39,6 +42,7 @@ func startBootstrapSignerController(ctx context.Context, controllerContext Contr
 }
 
 func startTokenCleanerController(ctx context.Context, controllerContext ControllerContext) (controller.Interface, bool, error) {
+	ctx = klog.NewContext(ctx, klog.LoggerWithName(klog.FromContext(ctx), "token-cleaner-controller"))
 	tcc, err := bootstrap.NewTokenCleaner(
 		controllerContext.ClientBuilder.ClientOrDie("token-cleaner"),
 		controllerContext.InformerFactory.Core().V1().Secrets(),

pkg/controller/bootstrap/bootstrapsigner.go

@@ -158,10 +158,11 @@ func (e *Signer) Run(ctx context.Context) {
 		return
 	}
 
-	klog.V(5).Infof("Starting workers")
+	logger := klog.FromContext(ctx)
+	logger.V(5).Info("Starting workers")
 	go wait.UntilWithContext(ctx, e.serviceConfigMapQueue, 0)
 	<-ctx.Done()
-	klog.V(1).Infof("Shutting down")
+	logger.V(1).Info("Shutting down")
 }
 
 func (e *Signer) pokeConfigMapSync() {
@@ -191,10 +192,12 @@ func (e *Signer) signConfigMap(ctx context.Context) {
 
 	newCM := origCM.DeepCopy()
 
+	logger := klog.FromContext(ctx)
+
 	// First capture the config we are signing
 	content, ok := newCM.Data[bootstrapapi.KubeConfigKey]
 	if !ok {
-		klog.V(3).Infof("No %s key in %s/%s ConfigMap", bootstrapapi.KubeConfigKey, origCM.Namespace, origCM.Name)
+		logger.V(3).Info("No key in ConfigMap", "key", bootstrapapi.KubeConfigKey, "configMap", klog.KObj(origCM))
 		return
 	}
 
@@ -209,7 +212,7 @@ func (e *Signer) signConfigMap(ctx context.Context) {
 	}
 
 	// Now recompute signatures and store them on the new map
-	tokens := e.getTokens()
+	tokens := e.getTokens(ctx)
 	for tokenID, tokenValue := range tokens {
 		sig, err := jws.ComputeDetachedSignature(content, tokenID, tokenValue)
 		if err != nil {
@@ -240,7 +243,7 @@ func (e *Signer) signConfigMap(ctx context.Context) {
 func (e *Signer) updateConfigMap(ctx context.Context, cm *v1.ConfigMap) {
 	_, err := e.client.CoreV1().ConfigMaps(cm.Namespace).Update(ctx, cm, metav1.UpdateOptions{})
 	if err != nil && !apierrors.IsConflict(err) && !apierrors.IsNotFound(err) {
-		klog.V(3).Infof("Error updating ConfigMap: %v", err)
+		klog.FromContext(ctx).V(3).Info("Error updating ConfigMap", "err", err)
 	}
 }
 
@@ -278,11 +281,11 @@ func (e *Signer) listSecrets() []*v1.Secret {
 
 // getTokens returns a map of tokenID->tokenSecret. It ensures the token is
 // valid for signing.
-func (e *Signer) getTokens() map[string]string {
+func (e *Signer) getTokens(ctx context.Context) map[string]string {
 	ret := map[string]string{}
 	secretObjs := e.listSecrets()
 	for _, secret := range secretObjs {
-		tokenID, tokenSecret, ok := validateSecretForSigning(secret)
+		tokenID, tokenSecret, ok := validateSecretForSigning(ctx, secret)
 		if !ok {
 			continue
 		}
@@ -291,7 +294,7 @@ func (e *Signer) getTokens() map[string]string {
 		if _, ok := ret[tokenID]; ok {
 			// This should never happen as we ensure a consistent secret name.
 			// But leave this in here just in case.
-			klog.V(1).Infof("Duplicate bootstrap tokens found for id %s, ignoring on in %s/%s", tokenID, secret.Namespace, secret.Name)
+			klog.FromContext(ctx).V(1).Info("Duplicate bootstrap tokens found for id, ignoring on the duplicate secret", "tokenID", tokenID, "ignoredSecret", klog.KObj(secret))
 			continue
 		}
 

pkg/controller/bootstrap/tokencleaner.go

@@ -108,8 +108,9 @@ func (tc *TokenCleaner) Run(ctx context.Context) {
 	defer utilruntime.HandleCrash()
 	defer tc.queue.ShutDown()
 
-	klog.Infof("Starting token cleaner controller")
+	logger := klog.FromContext(ctx)
-	defer klog.Infof("Shutting down token cleaner controller")
+	logger.Info("Starting token cleaner controller")
+	defer logger.Info("Shutting down token cleaner controller")
 
 	if !cache.WaitForNamedCacheSync("token_cleaner", ctx.Done(), tc.secretSynced) {
 		return
@@ -154,9 +155,10 @@ func (tc *TokenCleaner) processNextWorkItem(ctx context.Context) bool {
 }
 
 func (tc *TokenCleaner) syncFunc(ctx context.Context, key string) error {
+	logger := klog.FromContext(ctx)
 	startTime := time.Now()
 	defer func() {
-		klog.V(4).Infof("Finished syncing secret %q (%v)", key, time.Since(startTime))
+		logger.V(4).Info("Finished syncing secret", "secret", key, "elapsedTime", time.Since(startTime))
 	}()
 
 	namespace, name, err := cache.SplitMetaNamespaceKey(key)
@@ -166,7 +168,7 @@ func (tc *TokenCleaner) syncFunc(ctx context.Context, key string) error {
 
 	ret, err := tc.secretLister.Secrets(namespace).Get(name)
 	if apierrors.IsNotFound(err) {
-		klog.V(3).Infof("secret has been deleted: %v", key)
+		logger.V(3).Info("Secret has been deleted", "secret", key)
 		return nil
 	}
 
@@ -181,10 +183,11 @@ func (tc *TokenCleaner) syncFunc(ctx context.Context, key string) error {
 }
 
 func (tc *TokenCleaner) evalSecret(ctx context.Context, o interface{}) {
+	logger := klog.FromContext(ctx)
 	secret := o.(*v1.Secret)
 	ttl, alreadyExpired := bootstrapsecretutil.GetExpiration(secret, time.Now())
 	if alreadyExpired {
-		klog.V(3).Infof("Deleting expired secret %s/%s", secret.Namespace, secret.Name)
+		logger.V(3).Info("Deleting expired secret", "secret", klog.KObj(secret))
 		var options metav1.DeleteOptions
 		if len(secret.UID) > 0 {
 			options.Preconditions = &metav1.Preconditions{UID: &secret.UID}
@@ -193,7 +196,7 @@ func (tc *TokenCleaner) evalSecret(ctx context.Context, o interface{}) {
 		// NotFound isn't a real error (it's already been deleted)
 		// Conflict isn't a real error (the UID precondition failed)
 		if err != nil && !apierrors.IsConflict(err) && !apierrors.IsNotFound(err) {
-			klog.V(3).Infof("Error deleting Secret: %v", err)
+			logger.V(3).Info("Error deleting secret", "err", err)
 		}
 	} else if ttl > 0 {
 		key, err := controller.KeyFunc(o)

pkg/controller/bootstrap/util.go

@@ -17,6 +17,7 @@ limitations under the License.
 package bootstrap
 
 import (
+	"context"
 	"time"
 
 	"k8s.io/klog/v2"
@@ -26,27 +27,28 @@ import (
 	bootstrapsecretutil "k8s.io/cluster-bootstrap/util/secrets"
 )
 
-func validateSecretForSigning(secret *v1.Secret) (tokenID, tokenSecret string, ok bool) {
+func validateSecretForSigning(ctx context.Context, secret *v1.Secret) (tokenID, tokenSecret string, ok bool) {
+	logger := klog.FromContext(ctx)
 	nameTokenID, ok := bootstrapsecretutil.ParseName(secret.Name)
 	if !ok {
-		klog.V(3).Infof("Invalid secret name: %s. Must be of form %s<secret-id>.", secret.Name, bootstrapapi.BootstrapTokenSecretPrefix)
+		logger.V(3).Info("Invalid secret name, must be of the form "+bootstrapapi.BootstrapTokenSecretPrefix+"<secret-id>", "secretName", secret.Name)
 		return "", "", false
 	}
 
 	tokenID = bootstrapsecretutil.GetData(secret, bootstrapapi.BootstrapTokenIDKey)
 	if len(tokenID) == 0 {
-		klog.V(3).Infof("No %s key in %s/%s Secret", bootstrapapi.BootstrapTokenIDKey, secret.Namespace, secret.Name)
+		logger.V(3).Info("No key in Secret", "key", bootstrapapi.BootstrapTokenIDKey, "secret", klog.KObj(secret))
 		return "", "", false
 	}
 
 	if nameTokenID != tokenID {
-		klog.V(3).Infof("Token ID (%s) doesn't match secret name: %s", tokenID, nameTokenID)
+		logger.V(3).Info("Token ID doesn't match secret name", "tokenID", tokenID, "secretName", secret.Name)
 		return "", "", false
 	}
 
 	tokenSecret = bootstrapsecretutil.GetData(secret, bootstrapapi.BootstrapTokenSecretKey)
 	if len(tokenSecret) == 0 {
-		klog.V(3).Infof("No %s key in %s/%s Secret", bootstrapapi.BootstrapTokenSecretKey, secret.Namespace, secret.Name)
+		logger.V(3).Info("No key in secret", "key", bootstrapapi.BootstrapTokenSecretKey, "secret", klog.KObj(secret))
 		return "", "", false
 	}
 

pkg/controller/bootstrap/util_test.go

@@ -23,6 +23,7 @@ import (
 	"k8s.io/api/core/v1"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	bootstrapapi "k8s.io/cluster-bootstrap/token/api"
+	"k8s.io/klog/v2/ktesting"
 )
 
 const (
@@ -79,38 +80,42 @@ func TestValidateSecretForSigning(t *testing.T) {
 	}
 
 	for _, tc := range cases {
-		secret := &v1.Secret{
+		t.Run(tc.description, func(t *testing.T) {
-			ObjectMeta: metav1.ObjectMeta{
+			_, ctx := ktesting.NewTestContext(t)
-				Namespace:       metav1.NamespaceSystem,
+			secret := &v1.Secret{
-				Name:            bootstrapapi.BootstrapTokenSecretPrefix + givenTokenID,
+				ObjectMeta: metav1.ObjectMeta{
-				ResourceVersion: "1",
+					Namespace:       metav1.NamespaceSystem,
-			},
+					Name:            bootstrapapi.BootstrapTokenSecretPrefix + givenTokenID,
-			Type: bootstrapapi.SecretTypeBootstrapToken,
+					ResourceVersion: "1",
-			Data: map[string][]byte{
+				},
-				bootstrapapi.BootstrapTokenIDKey:           []byte(tc.tokenID),
+				Type: bootstrapapi.SecretTypeBootstrapToken,
-				bootstrapapi.BootstrapTokenSecretKey:       []byte(tc.tokenSecret),
+				Data: map[string][]byte{
-				bootstrapapi.BootstrapTokenUsageSigningKey: []byte(tc.okToSign),
+					bootstrapapi.BootstrapTokenIDKey:           []byte(tc.tokenID),
-				bootstrapapi.BootstrapTokenExpirationKey:   []byte(tc.expiration),
+					bootstrapapi.BootstrapTokenSecretKey:       []byte(tc.tokenSecret),
-			},
+					bootstrapapi.BootstrapTokenUsageSigningKey: []byte(tc.okToSign),
-		}
+					bootstrapapi.BootstrapTokenExpirationKey:   []byte(tc.expiration),
+				},
+			}
 
-		tokenID, tokenSecret, ok := validateSecretForSigning(secret)
+			tokenID, tokenSecret, ok := validateSecretForSigning(ctx, secret)
-		if ok != tc.valid {
+			if ok != tc.valid {
-			t.Errorf("%s: Unexpected validation failure. Expected %v, got %v", tc.description, tc.valid, ok)
+				t.Errorf("Unexpected validation failure. Expected %v, got %v", tc.valid, ok)
-		}
-		if ok {
-			if tokenID != tc.tokenID {
-				t.Errorf("%s: Unexpected Token ID. Expected %q, got %q", tc.description, givenTokenID, tokenID)
 			}
-			if tokenSecret != tc.tokenSecret {
+			if ok {
-				t.Errorf("%s: Unexpected Token Secret. Expected %q, got %q", tc.description, givenTokenSecret, tokenSecret)
+				if tokenID != tc.tokenID {
+					t.Errorf("Unexpected Token ID. Expected %q, got %q", givenTokenID, tokenID)
+				}
+				if tokenSecret != tc.tokenSecret {
+					t.Errorf("Unexpected Token Secret. Expected %q, got %q", givenTokenSecret, tokenSecret)
+				}
 			}
-		}
+		})
 	}
 
 }
 
 func TestValidateSecret(t *testing.T) {
+	_, ctx := ktesting.NewTestContext(t)
 	secret := &v1.Secret{
 		ObjectMeta: metav1.ObjectMeta{
 			Namespace:       metav1.NamespaceSystem,
@@ -125,7 +130,7 @@ func TestValidateSecret(t *testing.T) {
 		},
 	}
 
-	tokenID, tokenSecret, ok := validateSecretForSigning(secret)
+	tokenID, tokenSecret, ok := validateSecretForSigning(ctx, secret)
 	if !ok {
 		t.Errorf("Unexpected validation failure.")
 	}
@@ -138,6 +143,7 @@ func TestValidateSecret(t *testing.T) {
 }
 
 func TestBadSecretName(t *testing.T) {
+	_, ctx := ktesting.NewTestContext(t)
 	secret := &v1.Secret{
 		ObjectMeta: metav1.ObjectMeta{
 			Namespace:       metav1.NamespaceSystem,
@@ -152,13 +158,14 @@ func TestBadSecretName(t *testing.T) {
 		},
 	}
 
-	_, _, ok := validateSecretForSigning(secret)
+	_, _, ok := validateSecretForSigning(ctx, secret)
 	if ok {
 		t.Errorf("Token validation should fail with bad name")
 	}
 }
 
 func TestMismatchSecretName(t *testing.T) {
+	_, ctx := ktesting.NewTestContext(t)
 	secret := &v1.Secret{
 		ObjectMeta: metav1.ObjectMeta{
 			Namespace:       metav1.NamespaceSystem,
@@ -173,7 +180,7 @@ func TestMismatchSecretName(t *testing.T) {
 		},
 	}
 
-	_, _, ok := validateSecretForSigning(secret)
+	_, _, ok := validateSecretForSigning(ctx, secret)
 	if ok {
 		t.Errorf("Token validation should fail with mismatched name")
 	}