From a9be965bfa7c8778b663707f2e24d2ada7c089f6 Mon Sep 17 00:00:00 2001 From: Yauheni Kaliuta Date: Mon, 7 Oct 2024 23:10:38 +0300 Subject: [PATCH] logger: add logLevel to DSCI devFlags Jira: https://issues.redhat.com/browse/RHOAIENG-14713 This is a squashed commit of the patchset (original ids): 959f84d33fa9 ("logger: import controller-runtime zap as ctrlzap") b8d9cde99c12 ("logger: add logLevel to DSCI devFlags") 2d3efe27c38b ("components, logger: always use controller's logger") 1ef9266fbf23 ("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 --- README.md | 30 +++--- .../v1/dscinitialization_types.go | 4 + ...ion.opendatahub.io_dscinitializations.yaml | 5 + .../datasciencecluster_controller.go | 13 +-- .../dscinitialization_controller.go | 10 ++ docs/api-overview.md | 3 +- main.go | 2 +- pkg/logger/logger.go | 94 +++++++++++++------ 8 files changed, 101 insertions(+), 60 deletions(-) diff --git a/README.md b/README.md index b1b7971d47f..73a43ec3b50 100644 --- a/README.md +++ b/README.md @@ -222,8 +222,6 @@ 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 ` for example from CSV. Valid values for ``: "" (as default) || prod || production || devel || development. @@ -231,12 +229,9 @@ 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 diff --git a/apis/dscinitialization/v1/dscinitialization_types.go b/apis/dscinitialization/v1/dscinitialization_types.go index 50f758a5df8..7780bb193e5 100644 --- a/apis/dscinitialization/v1/dscinitialization_types.go +++ b/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 { diff --git a/config/crd/bases/dscinitialization.opendatahub.io_dscinitializations.yaml b/config/crd/bases/dscinitialization.opendatahub.io_dscinitializations.yaml index dd381696bb1..894772ea9a9 100644 --- a/config/crd/bases/dscinitialization.opendatahub.io_dscinitializations.yaml +++ b/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 diff --git a/controllers/datasciencecluster/datasciencecluster_controller.go b/controllers/datasciencecluster/datasciencecluster_controller.go index 8570f270028..9e06b95bb6c 100644 --- a/controllers/datasciencecluster/datasciencecluster_controller.go +++ b/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" @@ -313,8 +312,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 @@ -365,13 +363,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(err error, instance *dscv1.DataScienceCluster, message string) *dscv1.DataScienceCluster { diff --git a/controllers/dscinitialization/dscinitialization_controller.go b/controllers/dscinitialization/dscinitialization_controller.go index 845418ac843..d7f1cc16569 100644 --- a/controllers/dscinitialization/dscinitialization_controller.go +++ b/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" ) @@ -101,6 +102,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) diff --git a/docs/api-overview.md b/docs/api-overview.md index 3c963f15088..9c2e8971dde 100644 --- a/docs/api-overview.md +++ b/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]
| +| `logmode` _string_ | ## DEPRECATED ##: Ignored, use LogLevel instead | production | Enum: [devel development prod production default]
| +| `logLevel` _string_ | Override Zap log level. Can be "debug", "info", "error" or a number (more verbose). | | | #### Monitoring diff --git a/main.go b/main.go index a50b4c96b40..a146f8783df 100644 --- a/main.go +++ b/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() diff --git a/pkg/logger/logger.go b/pkg/logger/logger.go index ed569084b28..122ce002bff 100644 --- a/pkg/logger/logger.go +++ b/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) {