logger: add logLevel to DSCI devFlags (#1307)

Jira: https://issues.redhat.com/browse/RHOAIENG-14713

This is a squashed commit of the patchset (original ids):

959f84d ("logger: import controller-runtime zap as ctrlzap")
b8d9cde ("logger: add logLevel to DSCI devFlags")
2d3efe2 ("components, logger: always use controller's logger")
1ef9266 ("components, logger: use one function for ctx creation")

- logger: import controller-runtime zap as ctrlzap

To avoid patch polluting with the next changes where uber's zap is
imported as `zap`.

- logger: add logLevel to DSCI devFlags

Allow to override global zap log level from DSCI devFlags. Accepts
the same values as to `--zap-log-level` command line switch.

Use zap.AtomicLevel type to store loglevel. Locally use atomic to
store its value. We must store the structure itsel since command
line flags parser (ctrlzap.(*levelFlag).Set()) stores the structure
there. In its order ctrlzap.addDefault() stores pointers,
newOptions() always sets the level to avoid setting it by
addDefaults(). Otherwise SetLevel should handle both pointer and the
structure as logLevel atomic.Value.

It is ok to store structure of zap.AtomicLevel since it itself
contains a pointer to the atomic.Int32 and common level value is
changed then.

The parsing code is modified version of the one from
controller-runtime/pkg/log/zap/flag.go.

Deprecate DSCI.DevFlags.logmode.

- components, logger: always use controller's logger

Since the log level is overridable with its own field of devFlags,
do not use logmode anymore. It was used to create own logger with
own zap backend in case if devFlags exist.

Just add name and value to the existing logger instead.

Rename NewLoggerWithOptions back to NewLogger since former NewLogger
is removed.

Change component logger name. "DSC.Component" is redundant. It was
usuful when component's logger was created from scratch, but now
when it is always based on the reconciler's one, it's clear that it
is a part of DSC.

- components, logger: use one function for ctx creation

Move both logger and component creation to one function.

Just a cleanup.

Signed-off-by: Yauheni Kaliuta <ykaliuta@redhat.com>

README.md

@@ -222,21 +222,16 @@ This will ensure that the doc for the apis are updated accordingly.
 
 ### Enabled logging
 
-#### Controller level
-
 Global logger configuration can be changed with a command line switch `--log-mode <mode>`
 for example from CSV. Valid values for `<mode>`: "" (as default) || prod || production || devel || development.
 
 Verbosity level is INFO.
 To fine tune zap backend [standard operator sdk zap switches](https://sdk.operatorframework.io/docs/building-operators/golang/references/logging/)
 can be used.
 
-#### Component level
-
-Logger on components can be changed by DSCI devFlags during runtime.
-By default, if not set .spec.devFlags.logmode, it uses INFO level
-Modification applies to all components, not only these "Managed" ones.
-Update DSCI CR with .spec.devFlags.logmode, see example :
+Log level can be changed by DSCI devFlags during runtime by setting
+.spec.devFlags.logLevel. It accepts the same values as `--zap-log-level`
+command line switch. See example :
 
 ```console
 apiVersion: dscinitialization.opendatahub.io/v1
@@ -245,20 +240,17 @@ metadata:
   name: default-dsci
 spec:
   devFlags:
-    logmode: development
+    logLevel: debug
   ...
 ```
 
-Avaiable value for logmode is "devel", "development", "prod", "production".
-The first two work the same set to DEBUG level; the later two work the same as using ERROR level.
-
-| .spec.devFlags.logmode | stacktrace level | verbosity | Output   | Comments       |
-| ---------------------- | ---------------- | --------- | -------- | -------------- |
-| devel                  | WARN             | INFO      | Console  | lowest level, using epoch time  |
-| development            | WARN             | INFO      | Console  | same as devel  |
-| ""                     | ERROR            | INFO      | JSON     | default option |
-| prod                   | ERROR            | INFO      | JSON     | highest level, using human readable timestamp  |
-| production             | ERROR            | INFO      | JSON     | same as prod   |
+| logmode     | stacktrace level | verbosity | Output  | Comments                                      |
+|-------------|------------------|-----------|---------|-----------------------------------------------|
+| devel       | WARN             | INFO      | Console | lowest level, using epoch time                |
+| development | WARN             | INFO      | Console | same as devel                                 |
+| ""          | ERROR            | INFO      | JSON    | default option                                |
+| prod        | ERROR            | INFO      | JSON    | highest level, using human readable timestamp |
+| production  | ERROR            | INFO      | JSON    | same as prod                                  |
 
 ### Example DSCInitialization
 

apis/dscinitialization/v1/dscinitialization_types.go

@@ -83,9 +83,13 @@ type DevFlags struct {
 	// Custom manifests uri for odh-manifests
 	// +optional
 	ManifestsUri string `json:"manifestsUri,omitempty"`
+	// ## DEPRECATED ##: Ignored, use LogLevel instead
 	// +kubebuilder:validation:Enum=devel;development;prod;production;default
 	// +kubebuilder:default="production"
 	LogMode string `json:"logmode,omitempty"`
+	// Override Zap log level. Can be "debug", "info", "error" or a number (more verbose).
+	// +optional
+	LogLevel string `json:"logLevel,omitempty"`
 }
 
 type TrustedCABundleSpec struct {

config/crd/bases/dscinitialization.opendatahub.io_dscinitializations.yaml

@@ -67,8 +67,13 @@ spec:
                   Internal development useful field to test customizations.
                   This is not recommended to be used in production environment.
                 properties:
+                  logLevel:
+                    description: Override Zap log level. Can be "debug", "info", "error"
+                      or a number (more verbose).
+                    type: string
                   logmode:
                     default: production
+                    description: '## DEPRECATED ##: Ignored, use LogLevel instead'
                     enum:
                     - devel
                     - development

controllers/datasciencecluster/datasciencecluster_controller.go

@@ -57,7 +57,6 @@ import (
 	"github.com/opendatahub-io/opendatahub-operator/v2/components/modelregistry"
 	"github.com/opendatahub-io/opendatahub-operator/v2/controllers/status"
 	"github.com/opendatahub-io/opendatahub-operator/v2/pkg/cluster"
-	ctrlogger "github.com/opendatahub-io/opendatahub-operator/v2/pkg/logger"
 	annotations "github.com/opendatahub-io/opendatahub-operator/v2/pkg/metadata/annotations"
 	"github.com/opendatahub-io/opendatahub-operator/v2/pkg/metadata/labels"
 	"github.com/opendatahub-io/opendatahub-operator/v2/pkg/upgrade"
@@ -312,8 +311,7 @@ func (r *DataScienceClusterReconciler) reconcileSubComponent(ctx context.Context
 		}
 	}
 	// Reconcile component
-	componentLogger := newComponentLogger(log, componentName, r.DataScienceCluster.DSCISpec)
-	componentCtx := logf.IntoContext(ctx, componentLogger)
+	componentCtx := newComponentContext(ctx, log, componentName)
 	err := component.ReconcileComponent(componentCtx, r.Client, instance, r.DataScienceCluster.DSCISpec, platform, installedComponentValue)
 
 	// TODO: replace this hack with a full refactor of component status in the future
@@ -364,13 +362,8 @@ func (r *DataScienceClusterReconciler) reconcileSubComponent(ctx context.Context
 	return instance, nil
 }
 
-// newComponentLogger is a wrapper to add DSC name and extract log mode from DSCISpec.
-func newComponentLogger(logger logr.Logger, componentName string, dscispec *dsciv1.DSCInitializationSpec) logr.Logger {
-	mode := ""
-	if dscispec.DevFlags != nil {
-		mode = dscispec.DevFlags.LogMode
-	}
-	return ctrlogger.NewNamedLogger(logger, "DSC.Components."+componentName, mode)
+func newComponentContext(ctx context.Context, log logr.Logger, componentName string) context.Context {
+	return logf.IntoContext(ctx, log.WithName(componentName).WithValues("component", componentName))
 }
 
 func (r *DataScienceClusterReconciler) reportError(ctx context.Context, err error, instance *dscv1.DataScienceCluster, message string) *dscv1.DataScienceCluster {

controllers/dscinitialization/dscinitialization_controller.go

@@ -48,6 +48,7 @@ import (
 	"github.com/opendatahub-io/opendatahub-operator/v2/controllers/status"
 	"github.com/opendatahub-io/opendatahub-operator/v2/pkg/cluster"
 	"github.com/opendatahub-io/opendatahub-operator/v2/pkg/deploy"
+	"github.com/opendatahub-io/opendatahub-operator/v2/pkg/logger"
 	"github.com/opendatahub-io/opendatahub-operator/v2/pkg/trustedcabundle"
 	"github.com/opendatahub-io/opendatahub-operator/v2/pkg/upgrade"
 )
@@ -100,6 +101,15 @@ func (r *DSCInitializationReconciler) Reconcile(ctx context.Context, req ctrl.Re
 		instance = &instances.Items[0]
 	}
 
+	if instance.Spec.DevFlags != nil {
+		level := instance.Spec.DevFlags.LogLevel
+		log.V(1).Info("Setting log level", "level", level)
+		err := logger.SetLevel(level)
+		if err != nil {
+			log.Error(err, "Failed to set log level", "level", level)
+		}
+	}
+
 	if instance.ObjectMeta.DeletionTimestamp.IsZero() {
 		if !controllerutil.ContainsFinalizer(instance, finalizerName) {
 			log.Info("Adding finalizer for DSCInitialization", "name", instance.Name, "finalizer", finalizerName)

docs/api-overview.md

@@ -669,7 +669,8 @@ _Appears in:_
 | Field | Description | Default | Validation |
 | --- | --- | --- | --- |
 | `manifestsUri` _string_ | Custom manifests uri for odh-manifests |  |  |
-| `logmode` _string_ |  | production | Enum: [devel development prod production default] <br /> |
+| `logmode` _string_ | ## DEPRECATED ##: Ignored, use LogLevel instead | production | Enum: [devel development prod production default] <br /> |
+| `logLevel` _string_ | Override Zap log level. Can be "debug", "info", "error" or a number (more verbose). |  |  |
 
 
 #### Monitoring

main.go

@@ -146,7 +146,7 @@ func main() { //nolint:funlen,maintidx
 
 	flag.Parse()
 
-	ctrl.SetLogger(logger.NewLoggerWithOptions(logmode, &opts))
+	ctrl.SetLogger(logger.NewLogger(logmode, &opts))
 
 	// root context
 	ctx := ctrl.SetupSignalHandler()

pkg/logger/logger.go

@@ -1,57 +1,92 @@
 package logger
 
 import (
+	"errors"
 	"flag"
+	"fmt"
 	"os"
+	"strconv"
+	"strings"
+	"sync/atomic"
 
 	"github.com/go-logr/logr"
+	"go.uber.org/zap"
 	"go.uber.org/zap/zapcore"
-	"sigs.k8s.io/controller-runtime/pkg/log/zap"
+	ctrlzap "sigs.k8s.io/controller-runtime/pkg/log/zap"
 )
 
-// NewNamedLogger creates a new logger for a component.
-// If the mode is set (so can be different from the default one),
-// it will create a new logger with the specified mode's options.
-func NewNamedLogger(log logr.Logger, name string, mode string) logr.Logger {
-	if mode != "" {
-		log = NewLogger(mode)
-	}
-	return log.WithName(name)
+var logLevel atomic.Value
+
+// copy from controller-runtime/pkg/log/zap/flag.go.
+var levelStrings = map[string]zapcore.Level{
+	"debug": zap.DebugLevel,
+	"info":  zap.InfoLevel,
+	"error": zap.ErrorLevel,
 }
 
-func NewLoggerWithOptions(mode string, override *zap.Options) logr.Logger {
-	opts := newOptions(mode)
-	overrideOptions(opts, override)
-	return newLogger(opts)
+// adjusted copy from controller-runtime/pkg/log/zap/flag.go, keep the same argument name.
+func stringToLevel(flagValue string) (zapcore.Level, error) {
+	level, validLevel := levelStrings[strings.ToLower(flagValue)]
+	if validLevel {
+		return level, nil
+	}
+	logLevel, err := strconv.Atoi(flagValue)
+	if err != nil {
+		return 0, fmt.Errorf("invalid log level \"%s\"", flagValue)
+	}
+	if logLevel > 0 {
+		intLevel := -1 * logLevel
+		return zapcore.Level(int8(intLevel)), nil
+	}
+
+	return 0, fmt.Errorf("invalid log level \"%s\"", flagValue)
 }
 
-// in DSC component, to use different mode for logging, e.g. development, production
-// when not set mode it falls to "default" which is used by startup main.go.
-func NewLogger(mode string) logr.Logger {
-	return newLogger(newOptions(mode))
+func SetLevel(levelStr string) error {
+	if levelStr == "" {
+		return nil
+	}
+	levelNum, err := stringToLevel(levelStr)
+	if err != nil {
+		return err
+	}
+
+	// ctrlzap.addDefauls() uses a pointer to the AtomicLevel,
+	// but ctrlzap.(*levelFlag).Set() the structure itsef.
+	// So use the structure and always set the value in newOptions() to addDefaults() call
+	level, ok := logLevel.Load().(zap.AtomicLevel)
+	if !ok {
+		return errors.New("stored loglevel is not of type *zap.AtomicLevel")
+	}
+
+	level.SetLevel(levelNum)
+	return nil
 }
 
-func newLogger(opts *zap.Options) logr.Logger {
-	return zap.New(zap.UseFlagOptions(opts))
+func NewLogger(mode string, override *ctrlzap.Options) logr.Logger {
+	opts := newOptions(mode)
+	overrideOptions(opts, override)
+	logLevel.Store(opts.Level)
+	return ctrlzap.New(ctrlzap.UseFlagOptions(opts))
 }
 
-func newOptions(mode string) *zap.Options {
-	var opts zap.Options
+func newOptions(mode string) *ctrlzap.Options {
+	var opts ctrlzap.Options
+	level := zap.NewAtomicLevelAt(zapcore.InfoLevel)
+
 	switch mode {
 	case "devel", "development": //  the most logging verbosity
-		opts = zap.Options{
+		opts = ctrlzap.Options{
 			Development:     true,
 			StacktraceLevel: zapcore.WarnLevel,
-			Level:           zapcore.InfoLevel,
 			DestWriter:      os.Stdout,
 		}
 	case "prod", "production": // the least logging verbosity
-		opts = zap.Options{
+		opts = ctrlzap.Options{
 			Development:     false,
 			StacktraceLevel: zapcore.ErrorLevel,
-			Level:           zapcore.InfoLevel,
 			DestWriter:      os.Stdout,
-			EncoderConfigOptions: []zap.EncoderConfigOption{func(config *zapcore.EncoderConfig) {
+			EncoderConfigOptions: []ctrlzap.EncoderConfigOption{func(config *zapcore.EncoderConfig) {
 				config.EncodeTime = zapcore.ISO8601TimeEncoder // human readable not epoch
 				config.EncodeDuration = zapcore.SecondsDurationEncoder
 				config.LevelKey = "LogLevel"
@@ -63,17 +98,18 @@ func newOptions(mode string) *zap.Options {
 			}},
 		}
 	default:
-		opts = zap.Options{
+		opts = ctrlzap.Options{
 			Development:     false,
 			StacktraceLevel: zapcore.ErrorLevel,
-			Level:           zapcore.InfoLevel,
 			DestWriter:      os.Stdout,
 		}
 	}
+
+	opts.Level = level
 	return &opts
 }
 
-func overrideOptions(orig, override *zap.Options) {
+func overrideOptions(orig, override *ctrlzap.Options) {
 	// Development is boolean, cannot check for nil, so check if it was set
 	isDevelopmentSet := false
 	flag.Visit(func(f *flag.Flag) {