Improve our logging setup (#1121)

controllers/cluster_controller.go

@@ -723,7 +723,7 @@ func checkCoordinatorValidity(cluster *fdbv1beta2.FoundationDBCluster, status *f
 
 // newFdbPodClient builds a client for working with an FDB Pod
 func newFdbPodClient(cluster *fdbv1beta2.FoundationDBCluster, pod *corev1.Pod) (podclient.FdbPodClient, error) {
-	return internal.NewFdbPodClient(cluster, pod)
+	return internal.NewFdbPodClient(cluster, pod, log.WithValues("namespace", cluster.Namespace, "cluster", cluster.Name, "pod", pod.Name))
 }
 
 func (r *FoundationDBClusterReconciler) getCoordinatorSet(cluster *fdbv1beta2.FoundationDBCluster) (map[string]struct{}, error) {

controllers/cluster_controller_test.go

@@ -3700,7 +3700,7 @@ var _ = Describe("cluster_controller", func() {
 			})
 
 			It("should be the public IP from the pod", func() {
-				result := podmanager.GetPublicIPs(pod)
+				result := podmanager.GetPublicIPs(pod, log)
 				Expect(result).To(Equal([]string{"1.1.1.1"}))
 			})
 		})
@@ -3719,7 +3719,7 @@ var _ = Describe("cluster_controller", func() {
 			})
 
 			It("should select the address based on the spec", func() {
-				result := podmanager.GetPublicIPs(pod)
+				result := podmanager.GetPublicIPs(pod, log)
 				Expect(result).To(Equal([]string{"2001:db8::ff00:42:8329"}))
 			})
 
@@ -3734,7 +3734,7 @@ var _ = Describe("cluster_controller", func() {
 				})
 
 				It("should be empty", func() {
-					result := podmanager.GetPublicIPs(pod)
+					result := podmanager.GetPublicIPs(pod, log)
 					Expect(result).To(BeEmpty())
 				})
 			})
@@ -3754,14 +3754,14 @@ var _ = Describe("cluster_controller", func() {
 			})
 
 			It("should select the address based on the spec", func() {
-				result := podmanager.GetPublicIPs(pod)
+				result := podmanager.GetPublicIPs(pod, log)
 				Expect(result).To(Equal([]string{"1.1.1.2"}))
 			})
 		})
 
 		Context("with no pod", func() {
 			It("should be empty", func() {
-				result := podmanager.GetPublicIPs(nil)
+				result := podmanager.GetPublicIPs(nil, log)
 				Expect(result).To(BeEmpty())
 			})
 		})

controllers/update_status.go

@@ -424,7 +424,7 @@ func validateProcessGroups(ctx context.Context, r *FoundationDBClusterReconciler
 
 		pod := pods[0]
 
-		processGroup.AddAddresses(podmanager.GetPublicIPs(pod), processGroup.IsMarkedForRemoval() || !status.Health.Available)
+		processGroup.AddAddresses(podmanager.GetPublicIPs(pod, log), processGroup.IsMarkedForRemoval() || !status.Health.Available)
 		processCount := 1
 
 		if processGroup.IsMarkedForRemoval() && pod.ObjectMeta.DeletionTimestamp != nil {

internal/log_file_cleaner.go

@@ -26,8 +26,24 @@ import (
 	"regexp"
 	"strings"
 	"time"
+
+	"github.com/go-logr/logr"
 )
 
+// CliLogFileCleaner contains the logger and the minFileAge
+type CliLogFileCleaner struct {
+	log        logr.Logger
+	minFileAge time.Duration
+}
+
+// NewCliLogFileCleaner returns a new CliLogFileCleaner
+func NewCliLogFileCleaner(log logr.Logger, minFileAge time.Duration) *CliLogFileCleaner {
+	return &CliLogFileCleaner{
+		log:        log,
+		minFileAge: minFileAge,
+	}
+}
+
 func shouldRemoveLogFile(info os.FileInfo, now time.Time, minFileAge time.Duration) (bool, error) {
 	if info.IsDir() {
 		return false, nil
@@ -55,21 +71,21 @@ func shouldRemoveLogFile(info os.FileInfo, now time.Time, minFileAge time.Durati
 }
 
 // CleanupOldCliLogs removes old fdbcli log files.
-func CleanupOldCliLogs(minFileAge time.Duration) {
+func (c CliLogFileCleaner) CleanupOldCliLogs() {
 	logDir := os.Getenv("FDB_NETWORK_OPTION_TRACE_ENABLE")
 	if logDir == "" {
 		return
 	}
 
 	deletedCnt := 0
 
-	log.V(1).Info("Attempt to clean up old CLI log files", "logDir", logDir)
+	c.log.V(1).Info("Attempt to clean up old CLI log files", "logDir", logDir)
 	err := filepath.Walk(logDir, func(path string, info os.FileInfo, err error) error {
 		if err != nil {
 			return err
 		}
 
-		remove, err := shouldRemoveLogFile(info, time.Now(), minFileAge)
+		remove, err := shouldRemoveLogFile(info, time.Now(), c.minFileAge)
 		if err != nil {
 			return err
 		}
@@ -92,5 +108,9 @@ func CleanupOldCliLogs(minFileAge time.Duration) {
 		return nil
 	})
 
-	log.V(1).Info("Cleanup old CLI log files", "deleted files", deletedCnt, "error", err)
+	if err != nil {
+		c.log.Error(err, "error during old Cli log file clean up")
+	}
+
+	c.log.V(1).Info("Clean up old CLI log files", "deleted files", deletedCnt)
 }

internal/pod_client.go

@@ -36,6 +36,8 @@ import (
 	"strings"
 	"time"
 
+	logf "sigs.k8s.io/controller-runtime/pkg/log"
+
 	fdbv1beta2 "github.com/FoundationDB/fdb-kubernetes-operator/api/v1beta2"
 	"github.com/FoundationDB/fdb-kubernetes-operator/pkg/podclient"
 	monitorapi "github.com/apple/foundationdb/fdbkubernetesmonitor/api"
@@ -104,10 +106,9 @@ type realFdbPodAnnotationClient struct {
 }
 
 // NewFdbPodClient builds a client for working with an FDB Pod
-func NewFdbPodClient(cluster *fdbv1beta2.FoundationDBCluster, pod *corev1.Pod) (podclient.FdbPodClient, error) {
-	logger := log.WithValues("namespace", cluster.Namespace, "cluster", cluster.Name, "pod", pod.Name)
+func NewFdbPodClient(cluster *fdbv1beta2.FoundationDBCluster, pod *corev1.Pod, log logr.Logger) (podclient.FdbPodClient, error) {
 	if GetImageType(pod) == FDBImageTypeUnified {
-		return &realFdbPodAnnotationClient{Cluster: cluster, Pod: pod, logger: logger}, nil
+		return &realFdbPodAnnotationClient{Cluster: cluster, Pod: pod, logger: log}, nil
 	}
 
 	if pod.Status.PodIP == "" {
@@ -151,12 +152,12 @@ func NewFdbPodClient(cluster *fdbv1beta2.FoundationDBCluster, pod *corev1.Pod) (
 		tlsConfig.RootCAs = certPool
 	}
 
-	return &realFdbPodSidecarClient{Cluster: cluster, Pod: pod, useTLS: useTLS, tlsConfig: tlsConfig, logger: logger}, nil
+	return &realFdbPodSidecarClient{Cluster: cluster, Pod: pod, useTLS: useTLS, tlsConfig: tlsConfig, logger: log}, nil
 }
 
 // getListenIP gets the IP address that a pod listens on.
 func (client *realFdbPodSidecarClient) getListenIP() string {
-	ips := GetPublicIPsForPod(client.Pod)
+	ips := GetPublicIPsForPod(client.Pod, client.logger)
 	if len(ips) > 0 {
 		return ips[0]
 	}
@@ -362,11 +363,12 @@ func (client *realFdbPodAnnotationClient) IsPresent(_ string) (bool, error) {
 type mockFdbPodClient struct {
 	Cluster *fdbv1beta2.FoundationDBCluster
 	Pod     *corev1.Pod
+	logger  logr.Logger
 }
 
 // NewMockFdbPodClient builds a mock client for working with an FDB pod
 func NewMockFdbPodClient(cluster *fdbv1beta2.FoundationDBCluster, pod *corev1.Pod) (podclient.FdbPodClient, error) {
-	return &mockFdbPodClient{Cluster: cluster, Pod: pod}, nil
+	return &mockFdbPodClient{Cluster: cluster, Pod: pod, logger: logf.NullLogger{}}, nil
 }
 
 // UpdateFile checks if a file is up-to-date and tries to update it.
@@ -390,7 +392,7 @@ func (client *mockFdbPodClient) GetVariableSubstitutions() (map[string]string, e
 		}
 	}
 
-	ipString := GetPublicIPsForPod(client.Pod)[0]
+	ipString := GetPublicIPsForPod(client.Pod, client.logger)[0]
 	substitutions["FDB_PUBLIC_IP"] = ipString
 	if ipString != "" {
 		ip := net.ParseIP(ipString)

internal/pod_helper.go

@@ -29,6 +29,8 @@ import (
 	"regexp"
 	"strconv"
 
+	"github.com/go-logr/logr"
+
 	"k8s.io/utils/pointer"
 
 	fdbv1beta2 "github.com/FoundationDB/fdb-kubernetes-operator/api/v1beta2"
@@ -40,7 +42,7 @@ import (
 var processGroupIDRegex = regexp.MustCompile(`^([\w-]+)-(\d+)`)
 
 // GetPublicIPsForPod returns the public IPs for a Pod
-func GetPublicIPsForPod(pod *corev1.Pod) []string {
+func GetPublicIPsForPod(pod *corev1.Pod, log logr.Logger) []string {
 	var podIPFamily *int
 
 	if pod == nil {

pkg/podmanager/fdb_process_group.go

@@ -24,14 +24,16 @@ import (
 	"fmt"
 	"regexp"
 
+	"github.com/go-logr/logr"
+
 	fdbv1beta2 "github.com/FoundationDB/fdb-kubernetes-operator/api/v1beta2"
 	"github.com/FoundationDB/fdb-kubernetes-operator/internal"
 	corev1 "k8s.io/api/core/v1"
 )
 
 var processIDRegex = regexp.MustCompile(`^([\w-]+-\d)-\d$`)
 
-// ParseProcessGroupID extracts the components of an process group ID.
+// ParseProcessGroupID extracts the components of a process group ID.
 func ParseProcessGroupID(id string) (fdbv1beta2.ProcessClass, int, error) {
 	return internal.ParseProcessGroupID(id)
 }
@@ -71,14 +73,14 @@ func GetPublicIPSource(pod *corev1.Pod) (fdbv1beta2.PublicIPSource, error) {
 }
 
 // GetPublicIPs returns the public IP of a pod.
-func GetPublicIPs(pod *corev1.Pod) []string {
+func GetPublicIPs(pod *corev1.Pod, log logr.Logger) []string {
 	if pod == nil {
 		return []string{}
 	}
 
 	source := pod.ObjectMeta.Annotations[fdbv1beta2.PublicIPSourceAnnotation]
 	if source == "" || source == string(fdbv1beta2.PublicIPSourcePod) {
-		return internal.GetPublicIPsForPod(pod)
+		return internal.GetPublicIPsForPod(pod, log)
 	}
 
 	return []string{pod.ObjectMeta.Annotations[fdbv1beta2.PublicIPAnnotation]}

setup/setup.go

@@ -29,27 +29,23 @@ import (
 	"strings"
 	"time"
 
-	"github.com/FoundationDB/fdb-kubernetes-operator/api/v1beta2"
-
-	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
-
-	"sigs.k8s.io/controller-runtime/pkg/log"
-
-	"github.com/FoundationDB/fdb-kubernetes-operator/internal"
-	"gopkg.in/natefinch/lumberjack.v2"
-
-	"sigs.k8s.io/controller-runtime/pkg/manager"
+	"github.com/go-logr/logr"
 
+	"github.com/FoundationDB/fdb-kubernetes-operator/api/v1beta2"
 	"github.com/FoundationDB/fdb-kubernetes-operator/controllers"
 	"github.com/FoundationDB/fdb-kubernetes-operator/fdbclient"
+	"github.com/FoundationDB/fdb-kubernetes-operator/internal"
+	"gopkg.in/natefinch/lumberjack.v2"
+	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	"k8s.io/apimachinery/pkg/runtime"
 	"k8s.io/klog/v2"
 	ctrl "sigs.k8s.io/controller-runtime"
 	"sigs.k8s.io/controller-runtime/pkg/client"
+	"sigs.k8s.io/controller-runtime/pkg/log"
 	"sigs.k8s.io/controller-runtime/pkg/log/zap"
+	"sigs.k8s.io/controller-runtime/pkg/manager"
 )
 
-var setupLog = ctrl.Log.WithName("setup")
 var operatorVersion = "latest"
 
 // Options provides all configuration Options for the operator
@@ -137,6 +133,7 @@ func StartManager(
 	// Might be called by controller-runtime in the future: https://github.com/kubernetes-sigs/controller-runtime/issues/1420
 	klog.SetLogger(logger)
 
+	setupLog := logger.WithName("setup")
 	fdbclient.DefaultCLITimeout = operatorOpts.CliTimeout
 
 	options := ctrl.Options{
@@ -160,7 +157,7 @@ func StartManager(
 		os.Exit(1)
 	}
 
-	if err := moveFDBBinaries(); err != nil {
+	if err := moveFDBBinaries(setupLog); err != nil {
 		setupLog.Error(err, "unable to move FDB binaries")
 		os.Exit(1)
 	}
@@ -214,11 +211,12 @@ func StartManager(
 
 	if operatorOpts.CleanUpOldLogFile {
 		setupLog.V(1).Info("setup log file cleaner", "LogFileMinAge", operatorOpts.LogFileMinAge.String())
+		cleaner := internal.NewCliLogFileCleaner(logger, operatorOpts.LogFileMinAge)
 		ticker := time.NewTicker(operatorOpts.LogFileMinAge)
 		go func() {
 			for {
 				<-ticker.C
-				internal.CleanupOldCliLogs(operatorOpts.LogFileMinAge)
+				cleaner.CleanupOldCliLogs()
 			}
 		}()
 	}
@@ -230,7 +228,7 @@ func StartManager(
 
 // MoveFDBBinaries moves FDB binaries that are pulled from setup containers into
 // the correct locations.
-func moveFDBBinaries() error {
+func moveFDBBinaries(log logr.Logger) error {
 	binFile, err := os.Open(os.Getenv("FDB_BINARY_DIR"))
 	if err != nil {
 		return err
@@ -280,14 +278,14 @@ func moveFDBBinaries() error {
 				for _, versionBinEntry := range versionBinDir {
 					currentPath := path.Join(versionBinFile.Name(), versionBinEntry.Name())
 					newPath := path.Join(minorVersionPath, versionBinEntry.Name())
-					setupLog.Info("Moving FDB binary file", "currentPath", currentPath, "newPath", newPath)
+					log.Info("Moving FDB binary file", "currentPath", currentPath, "newPath", newPath)
 					err = os.Rename(currentPath, newPath)
 					if err != nil {
 						return err
 					}
 				}
 			}
-			versionBinFile.Close()
+			_ = versionBinFile.Close()
 
 			versionLibFile, err := os.Open(path.Join(binFile.Name(), binEntry.Name(), "lib", "libfdb_c.so"))
 			if err != nil && !os.IsNotExist(err) {
@@ -296,13 +294,13 @@ func moveFDBBinaries() error {
 			if err == nil {
 				currentPath := path.Join(versionLibFile.Name())
 				newPath := path.Join(libDir.Name(), fmt.Sprintf("libfdb_c_%s.so", version))
-				setupLog.Info("Moving FDB library file", "currentPath", currentPath, "newPath", newPath)
+				log.Info("Moving FDB library file", "currentPath", currentPath, "newPath", newPath)
 				err = os.Rename(currentPath, newPath)
 				if err != nil {
 					return err
 				}
 			}
-			versionLibFile.Close()
+			_ = versionLibFile.Close()
 		}
 	}