Merge pull request #290 from zlabjp/contextual-logging

Contextual logging
zlabjp · Jan 29, 2024 · 634af2e · 634af2e
2 parents c03fe00 + 448948f
commit 634af2e
Show file tree

Hide file tree

Showing 16 changed files with 755 additions and 496 deletions.
diff --git a/.golangci.yaml b/.golangci.yaml
@@ -6,7 +6,7 @@ linters:
   - exportloopref
   - gofmt
   - importas
-  - logrlint
+  - loggercheck
   - noctx
   - prealloc
   - revive

diff --git a/cmd/nghttpx-ingress-controller/main.go b/cmd/nghttpx-ingress-controller/main.go
@@ -110,9 +110,16 @@ var (
 )
 
 func main() {
+	log := klog.NewKlogr()
+
 	rootCmd := &cobra.Command{
 		Use: "nghttpx-ingress-controller",
-		Run: run,
+		Run: func(cmd *cobra.Command, args []string) {
+			// Contextual logging is enabled by default, but cli.Run disables it.  Enable it again.
+			klog.EnableContextualLogging(true)
+
+			run(klog.NewContext(context.Background(), log), cmd, args)
+		},
 	}
 
 	rootCmd.Flags().AddGoFlagSet(flag.CommandLine)
@@ -232,8 +239,10 @@ func main() {
 	os.Exit(code)
 }
 
-func run(*cobra.Command, []string) {
-	klog.Infof("Using build: %v - %v", gitRepo, version)
+func run(ctx context.Context, _ *cobra.Command, _ []string) {
+	log := klog.FromContext(ctx)
+
+	log.Info("Using build", "repository", gitRepo, "version", version)
 
 	var (
 		defaultSvcKey       *types.NamespacedName
@@ -244,48 +253,57 @@ func run(*cobra.Command, []string) {
 
 	if !internalDefaultBackend {
 		if defaultSvc == "" {
-			klog.Exitf("default-backend-service cannot be empty")
+			log.Error(nil, "default-backend-service cannot be empty")
+			os.Exit(1)
 		}
-		if ns, name, err := cache.SplitMetaNamespaceKey(defaultSvc); err != nil {
-			klog.Exitf("default-backend-service: invalid Service identifier %v: %v", defaultSvc, err)
-		} else {
-			defaultSvcKey = &types.NamespacedName{
-				Namespace: ns,
-				Name:      name,
-			}
+		ns, name, err := cache.SplitMetaNamespaceKey(defaultSvc)
+		if err != nil {
+			log.Error(err, "default-backend-service: Invalid Service identifier", "Service", defaultSvc)
+			os.Exit(1)
+		}
+
+		defaultSvcKey = &types.NamespacedName{
+			Namespace: ns,
+			Name:      name,
 		}
 	}
 
 	if publishSvc != "" {
-		if ns, name, err := cache.SplitMetaNamespaceKey(publishSvc); err != nil {
-			klog.Exitf("publish-service: invalid Service identifier %v: %v", publishSvc, err)
-		} else {
-			publishSvcKey = &types.NamespacedName{
-				Namespace: ns,
-				Name:      name,
-			}
+		ns, name, err := cache.SplitMetaNamespaceKey(publishSvc)
+		if err != nil {
+			log.Error(err, "publish-service: Invalid Service identifier", "Service", publishSvc)
+			os.Exit(1)
+		}
+
+		publishSvcKey = &types.NamespacedName{
+			Namespace: ns,
+			Name:      name,
 		}
 	}
 
 	if ngxConfigMap != "" {
-		if ns, name, err := cache.SplitMetaNamespaceKey(ngxConfigMap); err != nil {
-			klog.Exitf("nghttpx-configmap: invalid ConfigMap identifier %v: %v", ngxConfigMap, err)
-		} else {
-			nghttpxConfigMapKey = &types.NamespacedName{
-				Namespace: ns,
-				Name:      name,
-			}
+		ns, name, err := cache.SplitMetaNamespaceKey(ngxConfigMap)
+		if err != nil {
+			log.Error(err, "nghttpx-configmap: Invalid ConfigMap identifier", "Service", ngxConfigMap)
+			os.Exit(1)
+		}
+
+		nghttpxConfigMapKey = &types.NamespacedName{
+			Namespace: ns,
+			Name:      name,
 		}
 	}
 
 	if defaultTLSSecret != "" {
-		if ns, name, err := cache.SplitMetaNamespaceKey(defaultTLSSecret); err != nil {
-			klog.Exitf("default-tls-secret: invalid Secret identifier %v: %v", defaultTLSSecret, err)
-		} else {
-			defaultTLSSecretKey = &types.NamespacedName{
-				Namespace: ns,
-				Name:      name,
-			}
+		ns, name, err := cache.SplitMetaNamespaceKey(defaultTLSSecret)
+		if err != nil {
+			log.Error(err, "default-tls-secret: Invalid Secret identifier", "Service", defaultTLSSecret)
+			os.Exit(1)
+		}
+
+		defaultTLSSecretKey = &types.NamespacedName{
+			Namespace: ns,
+			Name:      name,
 		}
 	}
 
@@ -303,32 +321,37 @@ func run(*cobra.Command, []string) {
 		config, err = clientcmd.NewNonInteractiveDeferredLoadingClientConfig(&loadingRules, &configOverrides).ClientConfig()
 	}
 	if err != nil {
-		klog.Exitf("Could not get clientConfig: %v", err)
+		log.Error(err, "Unable to get clientConfig")
+		os.Exit(1)
 	}
 
 	config.QPS = clientQPS
 	config.Burst = clientBurst
 
 	clientset, err := clientset.NewForConfig(config)
 	if err != nil {
-		klog.Exitf("Failed to create clientset: %v", err)
+		log.Error(err, "Unable to create clientset")
+		os.Exit(1)
 	}
 
 	podInfo := types.NamespacedName{Name: os.Getenv("POD_NAME"), Namespace: os.Getenv("POD_NAMESPACE")}
 
 	if podInfo.Name == "" {
-		klog.Exit("POD_NAME environment variable cannot be empty.")
+		log.Error(nil, "POD_NAME environment variable cannot be empty.")
+		os.Exit(1)
 	}
 	if podInfo.Namespace == "" {
-		klog.Exit("POD_NAMESPACE environment variable cannot be empty.")
+		log.Error(nil, "POD_NAMESPACE environment variable cannot be empty.")
+		os.Exit(1)
 	}
 
 	thisPod, err := getThisPod(clientset, podInfo)
 	if err != nil {
-		klog.Exitf("Could not get Pod %v/%v: %v", podInfo.Namespace, podInfo.Name, err)
+		log.Error(err, "Unable to get Pod", "Pod", podInfo)
+		os.Exit(1)
 	}
 
-	eventBroadcasterCtx, cancel := context.WithCancel(context.Background())
+	eventBroadcasterCtx, cancel := context.WithCancel(ctx)
 	defer cancel()
 
 	eventBroadcaster := events.NewBroadcaster(&events.EventSinkImpl{Interface: clientset.EventsV1()})
@@ -383,19 +406,21 @@ func run(*cobra.Command, []string) {
 
 	lb, err := nghttpx.NewLoadBalancer(lbConfig)
 	if err != nil {
-		klog.Exit(err)
+		log.Error(err, "Unable to create LoadBalancer")
+		os.Exit(1)
 	}
 
-	lbc, err := controller.NewLoadBalancerController(clientset, lb, controllerConfig)
+	lbc, err := controller.NewLoadBalancerController(ctx, clientset, lb, controllerConfig)
 	if err != nil {
-		klog.Exit(err)
+		log.Error(err, "Unable to create LoadBalancerController")
+		os.Exit(1)
 	}
 
-	ctx, cancel := context.WithCancel(context.Background())
+	ctx, cancel = context.WithCancel(ctx)
 	defer cancel()
 
-	go registerHandlers(cancel)
-	go handleSigterm(cancel)
+	go registerHandlers(ctx, cancel)
+	go handleSigterm(ctx, cancel)
 
 	lbc.Run(ctx)
 
@@ -451,7 +476,9 @@ func (hc healthzChecker) Check(_ *http.Request) error {
 	return nil
 }
 
-func registerHandlers(cancel context.CancelFunc) {
+func registerHandlers(ctx context.Context, cancel context.CancelFunc) {
+	log := klog.FromContext(ctx)
+
 	mux := http.NewServeMux()
 	healthz.InstallHandler(mux, newHealthzChecker(nghttpxHealthPort))
 
@@ -474,14 +501,19 @@ func registerHandlers(cancel context.CancelFunc) {
 		Addr:    fmt.Sprintf(":%v", healthzPort),
 		Handler: mux,
 	}
-	klog.Exit(server.ListenAndServe())
+	if err := server.ListenAndServe(); err != nil {
+		log.Error(err, "Internal HTTP server returned error")
+		os.Exit(1)
+	}
 }
 
-func handleSigterm(cancel context.CancelFunc) {
+func handleSigterm(ctx context.Context, cancel context.CancelFunc) {
+	log := klog.FromContext(ctx)
+
 	signalChan := make(chan os.Signal, 1)
 	signal.Notify(signalChan, syscall.SIGTERM)
 	<-signalChan
-	klog.Infof("Received SIGTERM, shutting down")
+	log.Info("Received SIGTERM, shutting down")
 
 	cancel()
 }
diff --git a/pkg/controller/annotation.go b/pkg/controller/annotation.go
@@ -9,6 +9,7 @@
 package controller
 
 import (
+	"context"
 	"fmt"
 	"strings"
 
@@ -36,39 +37,41 @@ type ingressAnnotation map[string]string
 // NewBackendConfigMapper returns nghttpx.BackendConfigMapper by reading default-backend-config and backend-config annotations.  This
 // function applies default-backend-config to backend-config if it exists.  If invalid value is found, this function replaces them with the
 // default value (e.g., nghttpx.ProtocolH1 for proto).
-func (ia ingressAnnotation) NewBackendConfigMapper() *nghttpx.BackendConfigMapper {
+func (ia ingressAnnotation) NewBackendConfigMapper(ctx context.Context) *nghttpx.BackendConfigMapper {
+	log := klog.FromContext(ctx)
+
 	data := ia[backendConfigKey]
 	// the first key specifies service name, and secondary key specifies port name.
 	var config nghttpx.BackendConfigMapping
 	if data != "" {
-		if err := unmarshal([]byte(data), &config); err != nil {
-			klog.Errorf("unexpected error reading %v annotation: %v", backendConfigKey, err)
+		if err := unmarshal(ctx, []byte(data), &config); err != nil {
+			log.Error(err, "Unexpected error while reading annotation", "annotation", backendConfigKey)
 			return nghttpx.NewBackendConfigMapper(nil, nil)
 		}
 	}
 
 	for _, v := range config {
 		for _, vv := range v {
-			nghttpx.FixupBackendConfig(vv)
+			nghttpx.FixupBackendConfig(ctx, vv)
 		}
 	}
 
 	data = ia[defaultBackendConfigKey]
 	if data == "" {
-		klog.V(4).Infof("%v annotation not found", defaultBackendConfigKey)
+		log.V(4).Info("Annotation not found", "annoation", defaultBackendConfigKey)
 		return nghttpx.NewBackendConfigMapper(nil, config)
 	}
 
 	var defaultConfig nghttpx.BackendConfig
-	if err := unmarshal([]byte(data), &defaultConfig); err != nil {
-		klog.Errorf("unexpected error reading %v annotation: %v", defaultBackendConfigKey, err)
+	if err := unmarshal(ctx, []byte(data), &defaultConfig); err != nil {
+		log.Error(err, "Unexpected error while reading annotation", "annotation", defaultBackendConfigKey)
 		return nghttpx.NewBackendConfigMapper(nil, nil)
 	}
-	nghttpx.FixupBackendConfig(&defaultConfig)
+	nghttpx.FixupBackendConfig(ctx, &defaultConfig)
 
 	for _, v := range config {
 		for _, vv := range v {
-			nghttpx.ApplyDefaultBackendConfig(vv, &defaultConfig)
+			nghttpx.ApplyDefaultBackendConfig(ctx, vv, &defaultConfig)
 		}
 	}
 
@@ -77,37 +80,39 @@ func (ia ingressAnnotation) NewBackendConfigMapper() *nghttpx.BackendConfigMappe
 
 // NewPathConfigMapper returns nghttpx.PathConfigMapper by reading default-path-config and path-config annotation.  This function applies
 // default-path-config to path-config if a value is missing.
-func (ia ingressAnnotation) NewPathConfigMapper() *nghttpx.PathConfigMapper {
+func (ia ingressAnnotation) NewPathConfigMapper(ctx context.Context) *nghttpx.PathConfigMapper {
+	log := klog.FromContext(ctx)
+
 	data := ia[pathConfigKey]
 	var config nghttpx.PathConfigMapping
 	if data != "" {
-		if err := unmarshal([]byte(data), &config); err != nil {
-			klog.Errorf("unexpected error reading %v annotation: %v", pathConfigKey, err)
+		if err := unmarshal(ctx, []byte(data), &config); err != nil {
+			log.Error(err, "Unexpected error while reading annotation", "annotation", pathConfigKey)
 			return nghttpx.NewPathConfigMapper(nil, nil)
 		}
 	}
 
 	config = normalizePathKey(config)
 
 	for _, v := range config {
-		nghttpx.FixupPathConfig(v)
+		nghttpx.FixupPathConfig(ctx, v)
 	}
 
 	data = ia[defaultPathConfigKey]
 	if data == "" {
-		klog.V(4).Infof("%v annotation not found", defaultPathConfigKey)
+		log.V(4).Info("Annotation not found", "annotation", defaultPathConfigKey)
 		return nghttpx.NewPathConfigMapper(nil, config)
 	}
 
 	var defaultConfig nghttpx.PathConfig
-	if err := unmarshal([]byte(data), &defaultConfig); err != nil {
-		klog.Errorf("unexpected error reading %v annotation: %v", defaultPathConfigKey, err)
+	if err := unmarshal(ctx, []byte(data), &defaultConfig); err != nil {
+		log.Error(err, "Unexpected error while reading annotation", "annotation", defaultPathConfigKey)
 		return nghttpx.NewPathConfigMapper(nil, nil)
 	}
-	nghttpx.FixupPathConfig(&defaultConfig)
+	nghttpx.FixupPathConfig(ctx, &defaultConfig)
 
 	for _, v := range config {
-		nghttpx.ApplyDefaultPathConfig(v, &defaultConfig)
+		nghttpx.ApplyDefaultPathConfig(ctx, v, &defaultConfig)
 	}
 
 	return nghttpx.NewPathConfigMapper(&defaultConfig, config)
@@ -132,13 +137,15 @@ func normalizePathKey(src map[string]*nghttpx.PathConfig) map[string]*nghttpx.Pa
 }
 
 // unmarshal deserializes data into dest.  This function first tries YAML and then JSON.
-func unmarshal(data []byte, dest interface{}) error {
+func unmarshal(ctx context.Context, data []byte, dest interface{}) error {
+	log := klog.FromContext(ctx)
+
 	err := yaml.Unmarshal(data, dest)
 	if err == nil {
 		return nil
 	}
 
-	klog.Infof("Could not unmarshal YAML string; fall back to JSON: %v", err)
+	log.Error(err, "Unable to unmarshal YAML string; fall back to JSON")
 
 	if err := json.Unmarshal(data, dest); err != nil {
 		return fmt.Errorf("could not unmarshal JSON string: %w", err)

diff --git a/pkg/controller/annotation_test.go b/pkg/controller/annotation_test.go
@@ -1,6 +1,7 @@
 package controller
 
 import (
+	"context"
 	"reflect"
 	"testing"
 	"time"
@@ -86,7 +87,7 @@ svc:
 				defaultBackendConfigKey: tt.annotationDefaultConfig,
 				backendConfigKey:        tt.annotationConfig,
 			})
-			bcm := ann.NewBackendConfigMapper()
+			bcm := ann.NewBackendConfigMapper(context.Background())
 
 			if !reflect.DeepEqual(bcm.DefaultBackendConfig, tt.wantDefaultConfig) {
 				t.Errorf("bcm.DefaultBackendConfig = %+v, want %+v", bcm.DefaultBackendConfig, tt.wantDefaultConfig)
@@ -161,7 +162,7 @@ example.com/alpha:
 				defaultPathConfigKey: tt.annotationDefaultConfig,
 				pathConfigKey:        tt.annotationConfig,
 			})
-			pcm := ann.NewPathConfigMapper()
+			pcm := ann.NewPathConfigMapper(context.Background())
 
 			if !reflect.DeepEqual(pcm.DefaultPathConfig, tt.wantDefaultConfig) {
 				t.Errorf("pcm.DefaultPathConfig = %+v, want %+v", pcm.DefaultPathConfig, tt.wantDefaultConfig)