From 052f15768cf5afccee0dfd12059147e652c4e75e Mon Sep 17 00:00:00 2001 From: ilewis Date: Wed, 13 Nov 2024 13:23:47 +0000 Subject: [PATCH 1/7] Move config init to before logging init So that we can read log settings from config --- cmd/main.go | 4 ++-- utils/utils.go | 19 +++++++++---------- 2 files changed, 11 insertions(+), 12 deletions(-) diff --git a/cmd/main.go b/cmd/main.go index da573768..7d25bcd9 100644 --- a/cmd/main.go +++ b/cmd/main.go @@ -78,6 +78,8 @@ func main() { "Enabling this will ensure there is only one active controller manager.") flag.Parse() + utils.CreateConfigMap(controller.OperatorName) + ctrl.SetLogger(zap.New(zap.UseDevMode(true))) // see https://github.com/operator-framework/operator-sdk/issues/1813 @@ -133,8 +135,6 @@ func main() { } // +kubebuilder:scaffold:builder - utils.CreateConfigMap(controller.OperatorName) - if err := mgr.AddHealthzCheck("healthz", healthz.Ping); err != nil { setupLog.Error(err, "unable to set up health check") os.Exit(1) diff --git a/utils/utils.go b/utils/utils.go index 4987de1e..61f4308d 100644 --- a/utils/utils.go +++ b/utils/utils.go @@ -18,7 +18,6 @@ import ( "k8s.io/client-go/kubernetes/scheme" "k8s.io/client-go/rest" "k8s.io/client-go/tools/remotecommand" - ctrl "sigs.k8s.io/controller-runtime" "sigs.k8s.io/controller-runtime/pkg/client" clientcfg "sigs.k8s.io/controller-runtime/pkg/client/config" "sigs.k8s.io/controller-runtime/pkg/controller/controllerutil" @@ -1729,12 +1728,12 @@ func addSecretResourceVersionAsEnvVar(pts *corev1.PodTemplateSpec, object metav1 // This should only be called once from main.go on operator start // It checks for the presence of the operators config map and // creates it if it doesn't exist +// As we load logging config from the config map, we can't use log messages as the logger won't be setup yet. func CreateConfigMap(mapName string) { - utilsLog := ctrl.Log.WithName("utils-setup") - // This function is called from main, so the normal client isn't setup properly + // The config map may not be in a watched namespace, in which case the normal client won't read it. client, clerr := client.New(clientcfg.GetConfigOrDie(), client.Options{}) if clerr != nil { - utilsLog.Error(clerr, "Couldn't create a client for config map creation") + fmt.Fprintf(os.Stderr, "Couldn't create a client for config map creation: %s\n", clerr) return } @@ -1743,7 +1742,7 @@ func CreateConfigMap(mapName string) { // This could happen if the operator is running locally, i.e. outside the cluster watchNamespaces, err := GetWatchNamespaces() if err != nil { - utilsLog.Error(err, "Error getting watch namespace") + fmt.Fprintf(os.Stderr, "Error getting watch namespace: %s\n", err) return } // If the operator is running locally, use the first namespace in the `watchNamespaces` @@ -1752,12 +1751,12 @@ func CreateConfigMap(mapName string) { configMap := &corev1.ConfigMap{} err := client.Get(context.TODO(), types.NamespacedName{Name: mapName, Namespace: operatorNs}, configMap) if err != nil && apierrors.IsNotFound(err) { - utilsLog.Error(err, "The operator config map was not found. Attempting to create it") + fmt.Fprintf(os.Stderr, "The operator config map was not found. Attempting to create it: %s\n", err) } else if err != nil { - utilsLog.Error(err, "Couldn't retrieve operator config map") + fmt.Fprintf(os.Stderr, "Couldn't retrieve operator config map: %s\n", err) return } else { - utilsLog.Info("Existing operator config map was found") + fmt.Fprintf(os.Stderr, "Existing operator config map was found\n") return } @@ -1775,9 +1774,9 @@ func CreateConfigMap(mapName string) { return nil }) if cerr != nil { - utilsLog.Error(cerr, "Couldn't create config map in namespace "+operatorNs) + fmt.Fprintf(os.Stderr, "Couldn't create config map in namespace %s: %s\n", operatorNs, err) } else { - utilsLog.Info("Operator Config map created in namespace " + operatorNs) + fmt.Fprintf(os.Stderr, "Operator Config map created in namespace %s\n", operatorNs) } } From b0a45a1b48a2230b9d9662e902b01309171f6d46 Mon Sep 17 00:00:00 2001 From: ilewis Date: Wed, 13 Nov 2024 13:37:20 +0000 Subject: [PATCH 2/7] Log 'Reconciled' messages at debug1 level --- common/config.go | 4 ++++ utils/reconciler.go | 3 ++- 2 files changed, 6 insertions(+), 1 deletion(-) diff --git a/common/config.go b/common/config.go index 89ce8020..e1fc1940 100644 --- a/common/config.go +++ b/common/config.go @@ -17,6 +17,10 @@ const ( // OpConfigCMCADuration default duration for cert-manager issued service certificate OpConfigCMCertDuration = "certManagerCertDuration" + + // Constants to use when fetching a debug level logger + LogLevelDebug = 1 + LogLevelDebug2 = 2 ) // Config stores operator configuration diff --git a/utils/reconciler.go b/utils/reconciler.go index cdbabb4f..cdfdec9a 100644 --- a/utils/reconciler.go +++ b/utils/reconciler.go @@ -106,6 +106,7 @@ func (r *ReconcilerBase) SetDiscoveryClient(discovery discovery.DiscoveryInterfa } var log = logf.Log.WithName("utils") +var logD1 = log.V(common.LogLevelDebug) // CreateOrUpdate ... func (r *ReconcilerBase) CreateOrUpdate(obj client.Object, owner metav1.Object, reconcile func() error) error { @@ -122,7 +123,7 @@ func (r *ReconcilerBase) CreateOrUpdate(obj client.Object, owner metav1.Object, var gvk schema.GroupVersionKind gvk, err = apiutil.GVKForObject(obj, r.scheme) if err == nil { - log.Info("Reconciled", "Kind", gvk.Kind, "Namespace", obj.GetNamespace(), "Name", obj.GetName(), "Status", result) + logD1.Info("Reconciled", "Kind", gvk.Kind, "Namespace", obj.GetNamespace(), "Name", obj.GetName(), "Status", result) } return err From b5cbdbc3c4f31445b67e917dc339f369b8cfbb66 Mon Sep 17 00:00:00 2001 From: ilewis Date: Wed, 13 Nov 2024 15:16:17 +0000 Subject: [PATCH 3/7] Allow log level to be configured through config --- cmd/main.go | 12 +++++++++++- common/config.go | 40 ++++++++++++++++++++++++++++++++++++++++ 2 files changed, 51 insertions(+), 1 deletion(-) diff --git a/cmd/main.go b/cmd/main.go index 7d25bcd9..7f3844e0 100644 --- a/cmd/main.go +++ b/cmd/main.go @@ -22,6 +22,8 @@ import ( "os" "time" + uberzap "go.uber.org/zap" + "go.uber.org/zap/zapcore" "k8s.io/apimachinery/pkg/runtime" utilruntime "k8s.io/apimachinery/pkg/util/runtime" clientgoscheme "k8s.io/client-go/kubernetes/scheme" @@ -33,6 +35,7 @@ import ( "sigs.k8s.io/controller-runtime/pkg/webhook" appstacksv1 "github.com/application-stacks/runtime-component-operator/api/v1" + "github.com/application-stacks/runtime-component-operator/common" "github.com/application-stacks/runtime-component-operator/internal/controller" "github.com/application-stacks/runtime-component-operator/utils" certmanagerv1 "github.com/cert-manager/cert-manager/pkg/apis/certmanager/v1" @@ -80,7 +83,14 @@ func main() { utils.CreateConfigMap(controller.OperatorName) - ctrl.SetLogger(zap.New(zap.UseDevMode(true))) + levelFunc := uberzap.LevelEnablerFunc(func(lvl zapcore.Level) bool { + return lvl >= common.Config.GetZapLogLevel() + }) + opts := zap.Options{ + Level: levelFunc, + Development: true, + } + ctrl.SetLogger(zap.New(zap.UseFlagOptions(&opts))) // see https://github.com/operator-framework/operator-sdk/issues/1813 leaseDuration := 30 * time.Second diff --git a/common/config.go b/common/config.go index e1fc1940..af3bf11a 100644 --- a/common/config.go +++ b/common/config.go @@ -1,6 +1,7 @@ package common import ( + "go.uber.org/zap/zapcore" corev1 "k8s.io/api/core/v1" ) @@ -18,9 +19,24 @@ const ( // OpConfigCMCADuration default duration for cert-manager issued service certificate OpConfigCMCertDuration = "certManagerCertDuration" + // OpConfigLogLevel the level of logs to be written + OpConfigLogLevel = "logLevel" + + // The allowed values for OpConfigLogLevel + logLevelWarning = "warning" + logLevelInfo = "info" + logLevelDebug = "debug" + logLevelDebug2 = "debug2" + // Constants to use when fetching a debug level logger LogLevelDebug = 1 LogLevelDebug2 = 2 + + // zap logging level constants + zLevelWarn zapcore.Level = 1 + zLevelInfo zapcore.Level = 0 + zLevelDebug zapcore.Level = -1 + zLevelDebug2 zapcore.Level = -2 ) // Config stores operator configuration @@ -37,11 +53,35 @@ func (oc OpConfig) LoadFromConfigMap(cm *corev1.ConfigMap) { } } +// Returns the zap log level corresponding to the value of the +// 'logLevel' key in the config map. Returns 'info' if they key +// is missing or contains an invalid value. +func (oc OpConfig) GetZapLogLevel() zapcore.Level { + level, ok := oc[OpConfigLogLevel] + if !ok { + return zLevelInfo + } + switch level { + case logLevelWarning: + return zLevelWarn + case logLevelInfo: + return zLevelInfo + case logLevelDebug: + return zLevelDebug + case logLevelDebug2: + return zLevelDebug2 + default: + // config value is invalid. + return zLevelInfo + } +} + // DefaultOpConfig returns default configuration func DefaultOpConfig() OpConfig { cfg := OpConfig{} cfg[OpConfigDefaultHostname] = "" cfg[OpConfigCMCADuration] = "8766h" cfg[OpConfigCMCertDuration] = "2160h" + cfg[OpConfigLogLevel] = logLevelInfo return cfg } From 3ac9c8c7224b63eaa31d8ce07a2c359bf888c20a Mon Sep 17 00:00:00 2001 From: ilewis Date: Wed, 13 Nov 2024 16:52:24 +0000 Subject: [PATCH 4/7] Add debugmax to log everything This is needed as controller runtime logs some messages at V(5) --- common/config.go | 13 +++++++++---- 1 file changed, 9 insertions(+), 4 deletions(-) diff --git a/common/config.go b/common/config.go index af3bf11a..e8e4271e 100644 --- a/common/config.go +++ b/common/config.go @@ -23,10 +23,11 @@ const ( OpConfigLogLevel = "logLevel" // The allowed values for OpConfigLogLevel - logLevelWarning = "warning" - logLevelInfo = "info" - logLevelDebug = "debug" - logLevelDebug2 = "debug2" + logLevelWarning = "warning" + logLevelInfo = "info" + logLevelDebug = "debug" + logLevelDebug2 = "debug2" + logLevelDebugMax = "debugmax" // Constants to use when fetching a debug level logger LogLevelDebug = 1 @@ -37,6 +38,8 @@ const ( zLevelInfo zapcore.Level = 0 zLevelDebug zapcore.Level = -1 zLevelDebug2 zapcore.Level = -2 + // zapcore.Level is defined as int8, so this logs everything + zLevelDebugMax zapcore.Level = -127 ) // Config stores operator configuration @@ -70,6 +73,8 @@ func (oc OpConfig) GetZapLogLevel() zapcore.Level { return zLevelDebug case logLevelDebug2: return zLevelDebug2 + case logLevelDebugMax: + return zLevelDebugMax default: // config value is invalid. return zLevelInfo From cdc0287b52870576acdf383342ad21460569fd6e Mon Sep 17 00:00:00 2001 From: ilewis Date: Thu, 14 Nov 2024 10:13:19 +0000 Subject: [PATCH 5/7] Review comments --- common/config.go | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/common/config.go b/common/config.go index e8e4271e..09fab923 100644 --- a/common/config.go +++ b/common/config.go @@ -20,14 +20,14 @@ const ( OpConfigCMCertDuration = "certManagerCertDuration" // OpConfigLogLevel the level of logs to be written - OpConfigLogLevel = "logLevel" + OpConfigLogLevel = "operatorLogLevel" // The allowed values for OpConfigLogLevel logLevelWarning = "warning" logLevelInfo = "info" - logLevelDebug = "debug" - logLevelDebug2 = "debug2" - logLevelDebugMax = "debugmax" + logLevelDebug = "fine" + logLevelDebug2 = "finer" + logLevelDebugMax = "finest" // Constants to use when fetching a debug level logger LogLevelDebug = 1 From 286bccab77d04e5b1084dedc80f5025025a98fee Mon Sep 17 00:00:00 2001 From: ilewis Date: Tue, 19 Nov 2024 16:40:28 +0000 Subject: [PATCH 6/7] Only log stack traces in debug logs Only log stack traces for error or higher messages, and only log them when logging level is fine/finer/finest --- cmd/main.go | 19 +++++++++++++++++-- 1 file changed, 17 insertions(+), 2 deletions(-) diff --git a/cmd/main.go b/cmd/main.go index 7f3844e0..e71f0bce 100644 --- a/cmd/main.go +++ b/cmd/main.go @@ -86,9 +86,24 @@ func main() { levelFunc := uberzap.LevelEnablerFunc(func(lvl zapcore.Level) bool { return lvl >= common.Config.GetZapLogLevel() }) + stackLevelFunc := uberzap.LevelEnablerFunc(func(lvl zapcore.Level) bool { + configuredLevel := common.Config.GetZapLogLevel() + if configuredLevel > zapcore.DebugLevel { + // No stack traces unless fine/finer/finest has been requested + // Zap's debug is mapped to fine + return false + } + // Stack traces for error or worse (fatal/panic) + if lvl >= zapcore.ErrorLevel { + return true + } + // Logging is set to fine/finer/finest but msg is info or less. No stack trace + return false + }) opts := zap.Options{ - Level: levelFunc, - Development: true, + Level: levelFunc, + StacktraceLevel: stackLevelFunc, + Development: true, } ctrl.SetLogger(zap.New(zap.UseFlagOptions(&opts))) From 6100cd5e431f2a3c36eb638a9c0bf92dfa114544 Mon Sep 17 00:00:00 2001 From: ilewis Date: Tue, 19 Nov 2024 16:58:19 +0000 Subject: [PATCH 7/7] Move logging functions into common code --- cmd/main.go | 23 ++--------------------- common/config.go | 20 ++++++++++++++++++++ 2 files changed, 22 insertions(+), 21 deletions(-) diff --git a/cmd/main.go b/cmd/main.go index e71f0bce..8fd221a6 100644 --- a/cmd/main.go +++ b/cmd/main.go @@ -22,8 +22,6 @@ import ( "os" "time" - uberzap "go.uber.org/zap" - "go.uber.org/zap/zapcore" "k8s.io/apimachinery/pkg/runtime" utilruntime "k8s.io/apimachinery/pkg/util/runtime" clientgoscheme "k8s.io/client-go/kubernetes/scheme" @@ -83,26 +81,9 @@ func main() { utils.CreateConfigMap(controller.OperatorName) - levelFunc := uberzap.LevelEnablerFunc(func(lvl zapcore.Level) bool { - return lvl >= common.Config.GetZapLogLevel() - }) - stackLevelFunc := uberzap.LevelEnablerFunc(func(lvl zapcore.Level) bool { - configuredLevel := common.Config.GetZapLogLevel() - if configuredLevel > zapcore.DebugLevel { - // No stack traces unless fine/finer/finest has been requested - // Zap's debug is mapped to fine - return false - } - // Stack traces for error or worse (fatal/panic) - if lvl >= zapcore.ErrorLevel { - return true - } - // Logging is set to fine/finer/finest but msg is info or less. No stack trace - return false - }) opts := zap.Options{ - Level: levelFunc, - StacktraceLevel: stackLevelFunc, + Level: common.LevelFunc, + StacktraceLevel: common.StackLevelFunc, Development: true, } ctrl.SetLogger(zap.New(zap.UseFlagOptions(&opts))) diff --git a/common/config.go b/common/config.go index 09fab923..a1d7a8ba 100644 --- a/common/config.go +++ b/common/config.go @@ -1,6 +1,7 @@ package common import ( + uberzap "go.uber.org/zap" "go.uber.org/zap/zapcore" corev1 "k8s.io/api/core/v1" ) @@ -45,6 +46,25 @@ const ( // Config stores operator configuration var Config = OpConfig{} +var LevelFunc = uberzap.LevelEnablerFunc(func(lvl zapcore.Level) bool { + return lvl >= Config.GetZapLogLevel() +}) + +var StackLevelFunc = uberzap.LevelEnablerFunc(func(lvl zapcore.Level) bool { + configuredLevel := Config.GetZapLogLevel() + if configuredLevel > zapcore.DebugLevel { + // No stack traces unless fine/finer/finest has been requested + // Zap's debug is mapped to fine + return false + } + // Stack traces for error or worse (fatal/panic) + if lvl >= zapcore.ErrorLevel { + return true + } + // Logging is set to fine/finer/finest but msg is info or less. No stack trace + return false +}) + // LoadFromConfigMap creates a config out of kubernetes config map func (oc OpConfig) LoadFromConfigMap(cm *corev1.ConfigMap) { for k, v := range DefaultOpConfig() {