Add structured logging via zap (rancher#133)

* Add structured logging properly

use a centralized logger wrapper to work with controller and virt-kubelet

Signed-off-by: galal-hussein <[email protected]>

* Fix some log messages

Signed-off-by: galal-hussein <[email protected]>

* fixes

Signed-off-by: galal-hussein <[email protected]>

---------

Signed-off-by: galal-hussein <[email protected]>

go.mod

@@ -17,6 +17,7 @@ replace (
 )
 
 require (
+	github.com/go-logr/zapr v1.3.0
 	github.com/prometheus/client_model v0.6.1
 	github.com/rancher/dynamiclistener v1.27.5
 	github.com/sirupsen/logrus v1.9.3
@@ -30,8 +31,6 @@ require (
 	k8s.io/apimachinery v0.31.1
 	k8s.io/apiserver v0.31.0
 	k8s.io/client-go v0.31.0
-	k8s.io/klog v1.0.0
-	k8s.io/klog/v2 v2.130.1
 	k8s.io/metrics v0.29.1
 	k8s.io/utils v0.0.0-20240711033017-18e509b52bc8
 	sigs.k8s.io/controller-runtime v0.17.5
@@ -123,6 +122,7 @@ require (
 	gopkg.in/yaml.v3 v3.0.1 // indirect
 	k8s.io/apiextensions-apiserver v0.29.2 // indirect
 	k8s.io/component-base v0.29.2 // indirect
+	k8s.io/klog/v2 v2.130.1 // indirect
 	k8s.io/kms v0.29.2 // indirect
 	k8s.io/kube-openapi v0.0.0-20231010175941-2dd684a91f00 // indirect
 	sigs.k8s.io/apiserver-network-proxy/konnectivity-client v0.28.0 // indirect

go.sum

@@ -57,7 +57,6 @@ github.com/felixge/httpsnoop v1.0.3 h1:s/nj+GCswXYzN5v2DpNMuMQYe+0DDwt5WVCU6CWBd
 github.com/felixge/httpsnoop v1.0.3/go.mod h1:m8KPJKqk1gH5J9DgRY2ASl2lWCfGKXixSwevea8zH2U=
 github.com/fsnotify/fsnotify v1.7.0 h1:8JEhPFa5W2WU7YfeZzPNqzMP6Lwt7L2715Ggo0nosvA=
 github.com/fsnotify/fsnotify v1.7.0/go.mod h1:40Bi/Hjc2AVfZrqy+aj+yEI+/bRxZnMJyTJwOpGvigM=
-github.com/go-logr/logr v0.1.0/go.mod h1:ixOQHD9gLJUVQQ2ZOR7zLEifBX6tGkNJF4QyIY7sIas=
 github.com/go-logr/logr v1.2.2/go.mod h1:jdQByPbusPIv2/zmleS9BjJVeZ6kBagPoEUsqbVz/1A=
 github.com/go-logr/logr v1.4.1 h1:pKouT5E8xu9zeFC39JXRDukb6JFQPXM5p5I91188VAQ=
 github.com/go-logr/logr v1.4.1/go.mod h1:9T104GzyrTigFIr8wt5mBrctHMim0Nb2HLGrmQ40KvY=
@@ -396,8 +395,6 @@ k8s.io/client-go v0.29.1 h1:19B/+2NGEwnFLzt0uB5kNJnfTsbV8w6TgQRz9l7ti7A=
 k8s.io/client-go v0.29.1/go.mod h1:TDG/psL9hdet0TI9mGyHJSgRkW3H9JZk2dNEUS7bRks=
 k8s.io/component-base v0.29.2 h1:lpiLyuvPA9yV1aQwGLENYyK7n/8t6l3nn3zAtFTJYe8=
 k8s.io/component-base v0.29.2/go.mod h1:BfB3SLrefbZXiBfbM+2H1dlat21Uewg/5qtKOl8degM=
-k8s.io/klog v1.0.0 h1:Pt+yjF5aB1xDSVbau4VsWe+dQNzA0qv1LlXdC2dF6Q8=
-k8s.io/klog v1.0.0/go.mod h1:4Bi6QPql/J/LkTDqv7R/cd3hPo4k2DG6Ptcz060Ez5I=
 k8s.io/klog/v2 v2.130.1 h1:n9Xl7H1Xvksem4KFG4PYbdQCQxqc/tTUyrgXaOhHSzk=
 k8s.io/klog/v2 v2.130.1/go.mod h1:3Jpz1GvMt720eyJH1ckRHK1EDfpxISzJ7I9OYgaDtPE=
 k8s.io/kms v0.29.2 h1:MDsbp98gSlEQs7K7dqLKNNTwKFQRYYvO4UOlBOjNy6Y=

k3k-kubelet/kubelet.go

@@ -6,7 +6,6 @@ import (
 	"crypto/x509"
 	"fmt"
 	"net/http"
-	"os"
 	"time"
 
 	certutil "github.com/rancher/dynamiclistener/cert"
@@ -16,6 +15,7 @@ import (
 	"github.com/rancher/k3k/pkg/controller/cluster/server"
 	"github.com/rancher/k3k/pkg/controller/cluster/server/bootstrap"
 	"github.com/rancher/k3k/pkg/controller/kubeconfig"
+	k3klog "github.com/rancher/k3k/pkg/log"
 	"github.com/virtual-kubelet/virtual-kubelet/log"
 	"github.com/virtual-kubelet/virtual-kubelet/node"
 	"github.com/virtual-kubelet/virtual-kubelet/node/nodeutil"
@@ -32,7 +32,10 @@ import (
 	ctrlruntimeclient "sigs.k8s.io/controller-runtime/pkg/client"
 )
 
-var scheme = runtime.NewScheme()
+var (
+	scheme         = runtime.NewScheme()
+	k3kKubeletName = "k3k-kubelet"
+)
 
 func init() {
 	_ = clientgoscheme.AddToScheme(scheme)
@@ -46,9 +49,10 @@ type kubelet struct {
 	hostClient ctrlruntimeclient.Client
 	virtClient kubernetes.Interface
 	node       *nodeutil.Node
+	logger     *k3klog.Logger
 }
 
-func newKubelet(ctx context.Context, c *config) (*kubelet, error) {
+func newKubelet(ctx context.Context, c *config, logger *k3klog.Logger) (*kubelet, error) {
 	hostConfig, err := clientcmd.BuildConfigFromFlags("", c.HostConfigPath)
 	if err != nil {
 		return nil, err
@@ -75,6 +79,7 @@ func newKubelet(ctx context.Context, c *config) (*kubelet, error) {
 		hostConfig: hostConfig,
 		hostClient: hostClient,
 		virtClient: virtClient,
+		logger:     logger.Named(k3kKubeletName),
 	}, nil
 }
 
@@ -92,30 +97,19 @@ func (k *kubelet) registerNode(ctx context.Context, srvPort, namespace, name, ho
 
 func (k *kubelet) start(ctx context.Context) {
 	go func() {
-		logger, err := zap.NewProduction()
-		if err != nil {
-			fmt.Println("unable to create logger:", err.Error())
-			os.Exit(1)
-		}
-		wrapped := LogWrapper{
-			*logger.Sugar(),
-		}
-		ctx = log.WithLogger(ctx, &wrapped)
+		ctx = log.WithLogger(ctx, k.logger)
 		if err := k.node.Run(ctx); err != nil {
-			fmt.Println("node errored when running:", err.Error())
-			os.Exit(1)
+			k.logger.Fatalw("node errored when running", zap.Error(err))
 		}
 	}()
 	if err := k.node.WaitReady(context.Background(), time.Minute*1); err != nil {
-		fmt.Println("node was not ready within timeout of 1 minute:", err.Error())
-		os.Exit(1)
+		k.logger.Fatalw("node was not ready within timeout of 1 minute", zap.Error(err))
 	}
 	<-k.node.Done()
 	if err := k.node.Err(); err != nil {
-		fmt.Println("node stopped with an error:", err.Error())
-		os.Exit(1)
+		k.logger.Fatalw("node stopped with an error", zap.Error(err))
 	}
-	fmt.Println("node exited without an error")
+	k.logger.Info("node exited successfully")
 }
 
 func (k *kubelet) newProviderFunc(namespace, name, hostname string) nodeutil.NewProviderFunc {
@@ -255,19 +249,3 @@ func loadTLSConfig(ctx context.Context, hostClient ctrlruntimeclient.Client, clu
 		Certificates: []tls.Certificate{clientCert},
 	}, nil
 }
-
-type LogWrapper struct {
-	zap.SugaredLogger
-}
-
-func (l *LogWrapper) WithError(err error) log.Logger {
-	return l
-}
-
-func (l *LogWrapper) WithField(string, interface{}) log.Logger {
-	return l
-}
-
-func (l *LogWrapper) WithFields(field log.Fields) log.Logger {
-	return l
-}

k3k-kubelet/main.go

@@ -2,16 +2,19 @@ package main
 
 import (
 	"context"
-	"fmt"
 	"os"
 
+	"github.com/rancher/k3k/pkg/log"
 	"github.com/sirupsen/logrus"
 	"github.com/urfave/cli"
+	"go.uber.org/zap"
 )
 
 var (
 	configFile string
 	cfg        config
+	logger     *log.Logger
+	debug      bool
 )
 
 func main() {
@@ -69,6 +72,16 @@ func main() {
 			EnvVar:      "CONFIG_FILE",
 			Value:       "/etc/rancher/k3k/config.yaml",
 		},
+		cli.BoolFlag{
+			Name:        "debug",
+			Usage:       "Enable debug logging",
+			Destination: &debug,
+			EnvVar:      "DEBUG",
+		},
+	}
+	app.Before = func(clx *cli.Context) error {
+		logger = log.New(debug)
+		return nil
 	}
 	app.Action = run
 	if err := app.Run(os.Args); err != nil {
@@ -77,25 +90,21 @@ func main() {
 }
 
 func run(clx *cli.Context) {
+	ctx := context.Background()
 	if err := cfg.parse(configFile); err != nil {
-		fmt.Printf("failed to parse config file %s: %v", configFile, err)
-		os.Exit(1)
+		logger.Fatalw("failed to parse config file", "path", configFile, zap.Error(err))
 	}
 
 	if err := cfg.validate(); err != nil {
-		fmt.Printf("failed to validate config: %v", err)
-		os.Exit(1)
+		logger.Fatalw("failed to validate config", zap.Error(err))
 	}
-	ctx := context.Background()
-	k, err := newKubelet(ctx, &cfg)
+	k, err := newKubelet(ctx, &cfg, logger)
 	if err != nil {
-		fmt.Printf("failed to create new virtual kubelet instance: %v", err)
-		os.Exit(1)
+		logger.Fatalw("failed to create new virtual kubelet instance", zap.Error(err))
 	}
 
 	if err := k.registerNode(ctx, cfg.KubeletPort, cfg.ClusterNamespace, cfg.ClusterName, cfg.AgentHostname); err != nil {
-		fmt.Printf("failed to register new node: %v", err)
-		os.Exit(1)
+		logger.Fatalw("failed to register new node", zap.Error(err))
 	}
 
 	k.start(ctx)

main.go

@@ -6,16 +6,19 @@ import (
 	"fmt"
 	"os"
 
+	"github.com/go-logr/zapr"
 	"github.com/rancher/k3k/cli/cmds"
 	"github.com/rancher/k3k/pkg/apis/k3k.io/v1alpha1"
 	"github.com/rancher/k3k/pkg/controller/cluster"
 	"github.com/rancher/k3k/pkg/controller/clusterset"
+	"github.com/rancher/k3k/pkg/log"
 	"github.com/urfave/cli"
+	"go.uber.org/zap"
 	"k8s.io/apimachinery/pkg/runtime"
 	clientgoscheme "k8s.io/client-go/kubernetes/scheme"
 	"k8s.io/client-go/tools/clientcmd"
-	"k8s.io/klog/v2"
 	ctrl "sigs.k8s.io/controller-runtime"
+	ctrlruntimelog "sigs.k8s.io/controller-runtime/pkg/log"
 	"sigs.k8s.io/controller-runtime/pkg/manager"
 )
 
@@ -30,6 +33,8 @@ var (
 	clusterCIDR      string
 	sharedAgentImage string
 	kubeconfig       string
+	debug            bool
+	logger           *log.Logger
 	flags            = []cli.Flag{
 		cli.StringFlag{
 			Name:        "kubeconfig",
@@ -46,10 +51,16 @@ var (
 		cli.StringFlag{
 			Name:        "shared-agent-image",
 			EnvVar:      "SHARED_AGENT_IMAGE",
-			Usage:       "K3K Virtual Kubelet image ",
+			Usage:       "K3K Virtual Kubelet image",
 			Value:       "rancher/k3k:k3k-kubelet-dev",
 			Destination: &sharedAgentImage,
 		},
+		cli.BoolFlag{
+			Name:        "debug",
+			EnvVar:      "DEBUG",
+			Usage:       "Debug level logging",
+			Destination: &debug,
+		},
 	}
 )
 
@@ -63,9 +74,12 @@ func main() {
 	app.Flags = flags
 	app.Action = run
 	app.Version = version + " (" + gitCommit + ")"
-
+	app.Before = func(clx *cli.Context) error {
+		logger = log.New(debug)
+		return nil
+	}
 	if err := app.Run(os.Args); err != nil {
-		klog.Fatal(err)
+		logger.Fatalw("failed to run k3k controller", zap.Error(err))
 	}
 
 }
@@ -75,41 +89,42 @@ func run(clx *cli.Context) error {
 
 	restConfig, err := clientcmd.BuildConfigFromFlags("", kubeconfig)
 	if err != nil {
-		return fmt.Errorf("Failed to create config from kubeconfig file: %v", err)
+		return fmt.Errorf("failed to create config from kubeconfig file: %v", err)
 	}
 
 	mgr, err := ctrl.NewManager(restConfig, manager.Options{
 		Scheme: scheme,
 	})
 
 	if err != nil {
-		return fmt.Errorf("Failed to create new controller runtime manager: %v", err)
+		return fmt.Errorf("failed to create new controller runtime manager: %v", err)
 	}
-	if err := cluster.Add(ctx, mgr, sharedAgentImage); err != nil {
-		return fmt.Errorf("Failed to add the new cluster controller: %v", err)
+
+	ctrlruntimelog.SetLogger(zapr.NewLogger(logger.Desugar().WithOptions(zap.AddCallerSkip(1))))
+	logger.Info("adding cluster controller")
+	if err := cluster.Add(ctx, mgr, sharedAgentImage, logger); err != nil {
+		return fmt.Errorf("failed to add the new cluster controller: %v", err)
 	}
 
-	if err := cluster.AddPodController(ctx, mgr); err != nil {
-		return fmt.Errorf("Failed to add the new cluster controller: %v", err)
+	logger.Info("adding etcd pod controller")
+	if err := cluster.AddPodController(ctx, mgr, logger); err != nil {
+		return fmt.Errorf("failed to add the new cluster controller: %v", err)
 	}
-	klog.Info("adding clusterset controller")
-	if err := clusterset.Add(ctx, mgr, clusterCIDR); err != nil {
-		return fmt.Errorf("Failed to add the clusterset controller: %v", err)
+
+	logger.Info("adding clusterset controller")
+	if err := clusterset.Add(ctx, mgr, clusterCIDR, logger); err != nil {
+		return fmt.Errorf("failed to add the clusterset controller: %v", err)
 	}
 
 	if clusterCIDR == "" {
-		klog.Info("adding networkpolicy node controller")
-		if err := clusterset.AddNodeController(ctx, mgr); err != nil {
-			return fmt.Errorf("Failed to add the clusterset node controller: %v", err)
+		logger.Info("adding networkpolicy node controller")
+		if err := clusterset.AddNodeController(ctx, mgr, logger); err != nil {
+			return fmt.Errorf("failed to add the clusterset node controller: %v", err)
 		}
 	}
 
-	if err := cluster.AddPodController(ctx, mgr); err != nil {
-		return fmt.Errorf("Failed to add the new cluster controller: %v", err)
-	}
-
 	if err := mgr.Start(ctx); err != nil {
-		return fmt.Errorf("Failed to start the manager: %v", err)
+		return fmt.Errorf("failed to start the manager: %v", err)
 	}
 
 	return nil