-
Notifications
You must be signed in to change notification settings - Fork 27
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
feat: replace deprecated logger methods #546
base: main
Are you sure you want to change the base?
Conversation
8214cc0
to
0881a1f
Compare
@@ -1233,12 +1248,12 @@ func queueHasPendingModuleDeleteTask(q *queue.TaskQueue, moduleName string) bool | |||
// registerModules load all available modules from modules directory. | |||
func (mm *ModuleManager) registerModules(scriptEnabledExtender *script_extender.Extender) error { | |||
if mm.ModulesDir == "" { | |||
log.Warnf("Empty modules directory is passed! No modules to load.") | |||
log.Warn("Empty modules directory is passed! No modules to load.") |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
interesting discussion point about dots in logs
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Agree
@@ -72,7 +74,7 @@ func (fl *FileSystemLoader) getBasicModule(definition moduleDefinition, commonSt | |||
return m, nil | |||
} | |||
|
|||
// reads single directory and returns BasicModule | |||
// LoadModule reads single directory and returns BasicModule |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Prefferable to delete useless comment, not to refactor it.
Whats purpose of this comment?
It looks obvious.
LoadModule by given path and return BasicModule.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
LoadModule is a public function, which means it must contain a docstring to generate documentation on pkg.go.dev
Another question is that the documentation should be more detailed. But at a minimum, its writing must meet the standards.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
- Addon operator do not used as a library from external developers.
- We do not need to cover clear code by obvious comments.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This is where our opinions differ :)
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I think not only mine is different. We have a lot of codebase without comment coverage.
Looks like we need to start apply practices, that we'll bring in discussions.
Signed-off-by: Evsyukov Denis <denis.evsyukov@flant.com> diff --git c/.golangci.yaml i/.golangci.yaml index 34a2b6e..6243489 100644 --- c/.golangci.yaml +++ i/.golangci.yaml @@ -37,11 +37,6 @@ linters-settings: - prefix(github.com/flant/) goimports: local-prefixes: github.com/flant/ - # TODO: replace deprecated methods - # ignore deprecated - # https://staticcheck.dev/docs/checks/#SA1019 - staticcheck: - checks: ["all","-SA1019"] sloglint: # Enforce not mixing key-value pairs and attributes. no-mixed-args: true diff --git c/cmd/addon-operator/main.go i/cmd/addon-operator/main.go index d548892..a4d6e9e 100644 --- c/cmd/addon-operator/main.go +++ i/cmd/addon-operator/main.go @@ -95,11 +95,11 @@ func run(ctx context.Context, operator *addon_operator.AddonOperator) error { operator.SetupKubeConfigManager(bk) if err := operator.Setup(); err != nil { - operator.Logger.Fatalf("setup failed: %s\n", err) + operator.Logger.Fatal("setup failed", log.Err(err)) } if err := operator.Start(ctx); err != nil { - operator.Logger.Fatalf("start failed: %s\n", err) + operator.Logger.Fatal("start failed", log.Err(err)) } // Block action by waiting signals from OS. diff --git c/examples/700-go-hook/global-hooks/global-go-hook.go i/examples/700-go-hook/global-hooks/global-go-hook.go index 7b7c76c..9868bca 100644 --- c/examples/700-go-hook/global-hooks/global-go-hook.go +++ i/examples/700-go-hook/global-hooks/global-go-hook.go @@ -10,6 +10,6 @@ var _ = sdk.RegisterFunc(&gohook.HookConfig{ }, handler) func handler(input *gohook.HookInput) error { - input.Logger.Infof("Start Global Go hook") + input.Logger.Info("Start Global Go hook") return nil } diff --git c/examples/700-go-hook/modules/001-module-go-hooks/hooks/go_hooks.go i/examples/700-go-hook/modules/001-module-go-hooks/hooks/go_hooks.go index 5b8764c..b4ef753 100644 --- c/examples/700-go-hook/modules/001-module-go-hooks/hooks/go_hooks.go +++ i/examples/700-go-hook/modules/001-module-go-hooks/hooks/go_hooks.go @@ -1,6 +1,8 @@ package hooks import ( + "fmt" + "log/slog" "time" v1 "k8s.io/api/core/v1" @@ -54,11 +56,12 @@ func ObjFilter(obj *unstructured.Unstructured) (gohook.FilterResult, error) { func run(input *gohook.HookInput) error { for _, o := range input.Snapshots["pods"] { podSpec := o.(*podSpecFilteredObj) - input.Logger.Infof("Got podSpec: %+v", podSpec) + input.Logger.Info("Got podSpec", + slog.String("spec", fmt.Sprintf("%+v", podSpec))) } - input.Logger.Infof("Hello from on_kube.pods2! I have %d snapshots\n", - len(input.Snapshots)) + input.Logger.Info("Hello from on_kube.pods2! I have snapshots", + slog.Int("count", len(input.Snapshots))) input.MetricsCollector.Add("addon_go_hooks_total", 1.0, nil) diff --git c/pkg/addon-operator/admission_http_server.go i/pkg/addon-operator/admission_http_server.go index f9dea6a..3a6a2e7 100644 --- c/pkg/addon-operator/admission_http_server.go +++ i/pkg/addon-operator/admission_http_server.go @@ -3,6 +3,7 @@ package addon_operator import ( "context" "fmt" + "log/slog" "net/http" "path" "time" @@ -27,7 +28,8 @@ func NewAdmissionServer(listenPort, certsDir string) *AdmissionServer { func (as *AdmissionServer) RegisterHandler(route string, handler http.Handler) { if _, ok := as.routes[route]; ok { - log.Fatalf("Route %q is already registered", route) + log.Fatal("Route is already registered", + slog.String("route", route)) } as.routes[route] = handler @@ -41,7 +43,8 @@ func (as *AdmissionServer) start(ctx context.Context) { mux.Handle(route, handler) } - log.Debugf("Registered admission routes: %v", as.routes) + log.Debug("Registered admission routes", + slog.String("routes", fmt.Sprintf("%v", as.routes))) srv := &http.Server{ Addr: fmt.Sprintf(":%s", as.listenPort), @@ -67,7 +70,7 @@ func (as *AdmissionServer) start(ctx context.Context) { cancel() }() if err := srv.Shutdown(ctx); err != nil { - log.Fatalf("Server Shutdown Failed:%+v", err) + log.Fatal("Server Shutdown Failed", log.Err(err)) } }() } diff --git c/pkg/addon-operator/bootstrap.go i/pkg/addon-operator/bootstrap.go index 2ddafbe..1544f88 100644 --- c/pkg/addon-operator/bootstrap.go +++ i/pkg/addon-operator/bootstrap.go @@ -2,6 +2,7 @@ package addon_operator import ( "fmt" + "log/slog" "github.com/deckhouse/deckhouse/pkg/log" @@ -18,22 +19,24 @@ import ( func (op *AddonOperator) bootstrap() error { log.Info(shapp.AppStartMessage) - log.Infof("Search modules in: %s", app.ModulesDir) + log.Info("Search modules", + slog.String("path", app.ModulesDir)) - log.Infof("Addon-operator namespace: %s", op.DefaultNamespace) + log.Info("Addon-operator namespace", + slog.String("namespace", op.DefaultNamespace)) // Debug server. // TODO: rewrite shapp global variables to the addon-operator ones var err error op.DebugServer, err = shell_operator.RunDefaultDebugServer(shapp.DebugUnixSocket, shapp.DebugHttpServerAddr, op.Logger.Named("debug-server")) if err != nil { - log.Errorf("Fatal: start Debug server: %s", err) + log.Error("Fatal: start Debug server", log.Err(err)) return fmt.Errorf("start Debug server: %w", err) } err = op.Assemble(op.DebugServer) if err != nil { - log.Errorf("Fatal: %s", err) + log.Error("Fatal", log.Err(err)) return fmt.Errorf("assemble Debug server: %w", err) } @@ -68,7 +71,7 @@ func (op *AddonOperator) Assemble(debugServer *debug.Server) (err error) { // SetupKubeConfigManager sets manager, which reads configuration for Modules from a cluster func (op *AddonOperator) SetupKubeConfigManager(bk backend.ConfigHandler) { if op.KubeConfigManager != nil { - log.Warnf("KubeConfigManager is already set") + log.Warn("KubeConfigManager is already set") // return if kube config manager is already set return } diff --git c/pkg/addon-operator/operator.go i/pkg/addon-operator/operator.go index 88af829..93b8ff2 100644 --- c/pkg/addon-operator/operator.go +++ i/pkg/addon-operator/operator.go @@ -154,9 +154,9 @@ func NewAddonOperator(ctx context.Context, opts ...Option) *AddonOperator { DefaultNamespace: app.Namespace, ConvergeState: converge.NewConvergeState(), parallelTaskChannels: parallelTaskChannels{ - channels: make(map[string](chan parallelQueueEvent)), + channels: make(map[string]chan parallelQueueEvent), }, - discoveredGVKs: make(map[string]struct{}, 0), + discoveredGVKs: make(map[string]struct{}), } for _, opt := range opts { @@ -245,7 +245,8 @@ func (op *AddonOperator) Setup() error { if err != nil { return fmt.Errorf("global hooks directory: %s", err) } - log.Infof("global hooks directory: %s", globalHooksDir) + log.Info("global hooks directory", + slog.String("dir", globalHooksDir)) tempDir, err := ensureTempDirectory(shapp.TempDir) if err != nil { @@ -437,7 +438,8 @@ func (op *AddonOperator) RegisterManagerEventsHandlers() { "binding": string(htypes.Schedule), } logEntry := utils.EnrichLoggerWithLabels(op.Logger, logLabels) - logEntry.Debugf("Create tasks for 'schedule' event '%s'", crontab) + logEntry.Debug("Create tasks for 'schedule' event", + slog.String("event", crontab)) var tasks []sh_task.Task op.ModuleManager.HandleScheduleEvent(crontab, @@ -508,7 +510,8 @@ func (op *AddonOperator) RegisterManagerEventsHandlers() { "binding": string(htypes.OnKubernetesEvent), } logEntry := utils.EnrichLoggerWithLabels(op.Logger, logLabels) - logEntry.Debugf("Create tasks for 'kubernetes' event '%s'", kubeEvent.String()) + logEntry.Debug("Create tasks for 'kubernetes' event", + slog.String("event", kubeEvent.String())) var tasks []sh_task.Task op.ModuleManager.HandleKubeEvent(kubeEvent, @@ -735,7 +738,7 @@ func (op *AddonOperator) CreatePurgeTasks(modulesToPurge []string, t sh_task.Tas return newTasks } -// ApplyKubeConfigValues +// HandleApplyKubeConfigValues ... func (op *AddonOperator) HandleApplyKubeConfigValues(t sh_task.Task, logLabels map[string]string) (res queue.TaskResult) { var handleErr error defer trace.StartRegion(context.Background(), "HandleApplyKubeConfigValues").End() @@ -749,7 +752,9 @@ func (op *AddonOperator) HandleApplyKubeConfigValues(t sh_task.Task, logLabels m if handleErr != nil { res.Status = queue.Fail - logEntry.Errorf("HandleApplyKubeConfigValues failed, requeue task to retry after delay. Failed count is %d. Error: %s", t.GetFailureCount()+1, handleErr) + logEntry.Error("HandleApplyKubeConfigValues failed, requeue task to retry after delay.", + slog.Int("count", t.GetFailureCount()+1), + log.Err(handleErr)) op.engine.MetricStorage.CounterAdd("{PREFIX}modules_discover_errors_total", 1.0, map[string]string{}) t.UpdateFailureMessage(handleErr.Error()) t.WithQueuedAt(time.Now()) @@ -758,7 +763,7 @@ func (op *AddonOperator) HandleApplyKubeConfigValues(t sh_task.Task, logLabels m res.Status = queue.Success - logEntry.Debugf("HandleApplyKubeConfigValues success") + logEntry.Debug("HandleApplyKubeConfigValues success") return } @@ -769,7 +774,8 @@ func (op *AddonOperator) HandleConvergeModules(t sh_task.Task, logLabels map[str taskEvent, ok := t.GetProp(converge.ConvergeEventProp).(converge.ConvergeEvent) if !ok { - logEntry.Errorf("Possible bug! Wrong prop type in ConvergeModules: got %T(%#[1]v) instead string.", t.GetProp("event")) + logEntry.Error("Possible bug! Wrong prop type in ConvergeModules: got another type instead string.", + slog.String("type", fmt.Sprintf("%T(%#[1]v)", t.GetProp("event")))) res.Status = queue.Fail return res } @@ -781,7 +787,7 @@ func (op *AddonOperator) HandleConvergeModules(t sh_task.Task, logLabels map[str op.ConvergeState.PhaseLock.Lock() defer op.ConvergeState.PhaseLock.Unlock() if op.ConvergeState.Phase == converge.StandBy { - logEntry.Debugf("ConvergeModules: start") + logEntry.Debug("ConvergeModules: start") // Deduplicate tasks: remove ConvergeModules tasks right after the current task. RemoveAdjacentConvergeModules(op.engine.TaskQueues.GetByName(t.GetQueueName()), t.GetId(), logLabels, op.Logger) @@ -801,7 +807,7 @@ func (op *AddonOperator) HandleConvergeModules(t sh_task.Task, logLabels map[str } if op.ConvergeState.Phase == converge.WaitBeforeAll { - logEntry.Infof("ConvergeModules: beforeAll hooks done, run modules") + logEntry.Info("ConvergeModules: beforeAll hooks done, run modules") var state *module_manager.ModulesState state, handleErr = op.ModuleManager.RefreshEnabledState(t.GetLogLabels()) @@ -829,7 +835,7 @@ func (op *AddonOperator) HandleConvergeModules(t sh_task.Task, logLabels map[str } if op.ConvergeState.Phase == converge.WaitDeleteAndRunModules { - logEntry.Infof("ConvergeModules: ModuleRun tasks done, execute AfterAll global hooks") + logEntry.Info("ConvergeModules: ModuleRun tasks done, execute AfterAll global hooks") // Put AfterAll tasks before current task. tasks, handleErr := op.CreateAfterAllTasks(t.GetLogLabels(), hm.EventDescription) if handleErr == nil { @@ -846,21 +852,24 @@ func (op *AddonOperator) HandleConvergeModules(t sh_task.Task, logLabels map[str // It is the last phase of ConvergeModules task, reset operator's Converge phase. if op.ConvergeState.Phase == converge.WaitAfterAll { op.ConvergeState.Phase = converge.StandBy - logEntry.Infof("ConvergeModules task done") + logEntry.Info("ConvergeModules task done") res.Status = queue.Success return res } if handleErr != nil { res.Status = queue.Fail - logEntry.Errorf("ConvergeModules failed in phase '%s', requeue task to retry after delay. Failed count is %d. Error: %s", op.ConvergeState.Phase, t.GetFailureCount()+1, handleErr) + logEntry.Error("ConvergeModules failed, requeue task to retry after delay.", + slog.String("phase", string(op.ConvergeState.Phase)), + slog.Int("count", t.GetFailureCount()+1), + log.Err(handleErr)) op.engine.MetricStorage.CounterAdd("{PREFIX}modules_discover_errors_total", 1.0, map[string]string{}) t.UpdateFailureMessage(handleErr.Error()) t.WithQueuedAt(time.Now()) return res } - logEntry.Debugf("ConvergeModules success") + logEntry.Debug("ConvergeModules success") res.Status = queue.Success return res } @@ -971,12 +980,16 @@ func (op *AddonOperator) CreateAndStartQueuesForGlobalHooks() { h := op.ModuleManager.GetGlobalHook(hookName) for _, hookBinding := range h.GetHookConfig().Schedules { if op.CreateAndStartQueue(hookBinding.Queue) { - log.Debugf("Queue '%s' started for global 'schedule' hook %s", hookBinding.Queue, hookName) + log.Debug("Queue started for global 'schedule' hook", + slog.String("queue", hookBinding.Queue), + slog.String("hook", hookName)) } } for _, hookBinding := range h.GetHookConfig().OnKubernetesEvents { if op.CreateAndStartQueue(hookBinding.Queue) { - log.Debugf("Queue '%s' started for global 'kubernetes' hook %s", hookBinding.Queue, hookName) + log.Debug("Queue started for global 'kubernetes' hook", + slog.String("queue", hookBinding.Queue), + slog.String("hook", hookName)) } } } @@ -995,7 +1008,9 @@ func (op *AddonOperator) CreateAndStartQueuesForModuleHooks(moduleName string) { for _, hook := range scheduleHooks { for _, hookBinding := range hook.GetHookConfig().Schedules { if op.CreateAndStartQueue(hookBinding.Queue) { - log.Debugf("Queue '%s' started for module 'schedule' hook %s", hookBinding.Queue, hook.GetName()) + log.Debug("Queue started for module 'schedule'", + slog.String("queue", hookBinding.Queue), + slog.String("hook", hook.GetName())) } } } @@ -1004,7 +1019,9 @@ func (op *AddonOperator) CreateAndStartQueuesForModuleHooks(moduleName string) { for _, hook := range kubeEventsHooks { for _, hookBinding := range hook.GetHookConfig().OnKubernetesEvents { if op.CreateAndStartQueue(hookBinding.Queue) { - log.Debugf("Queue '%s' started for module 'kubernetes' hook %s", hookBinding.Queue, hook.GetName()) + log.Debug("Queue started for module 'kubernetes'", + slog.String("queue", hookBinding.Queue), + slog.String("hook", hook.GetName())) } } } @@ -1031,7 +1048,7 @@ func (op *AddonOperator) CreateAndStartParallelQueues() { for i := 0; i < app.NumberOfParallelQueues; i++ { queueName := fmt.Sprintf(app.ParallelQueueNamePattern, i) if op.engine.TaskQueues.GetByName(queueName) != nil { - log.Warnf("Parallel queue %s already exists", queueName) + log.Warn("Parallel queue already exists", slog.String("queue", queueName)) continue } op.engine.TaskQueues.NewNamedQueue(queueName, op.ParallelTasksHandler) @@ -1042,7 +1059,7 @@ func (op *AddonOperator) CreateAndStartParallelQueues() { func (op *AddonOperator) DrainModuleQueues(modName string) { m := op.ModuleManager.GetModule(modName) if m == nil { - log.Warnf("Module %q is absent when we try to drain its queue", modName) + log.Warn("Module is absent when we try to drain its queue", slog.String("module", modName)) return } @@ -1089,7 +1106,7 @@ func (op *AddonOperator) StartModuleManagerEventHandler() { eventLogEntry := utils.EnrichLoggerWithLabels(logEntry, logLabels) // if global hooks haven't been run yet, script enabled extender fails due to missing global values if op.globalHooksNotExecutedYet() { - eventLogEntry.Infof("Global hook dynamic modification detected, ignore until starting first converge") + eventLogEntry.Info("Global hook dynamic modification detected, ignore until starting first converge") break } @@ -1104,12 +1121,13 @@ func (op *AddonOperator) StartModuleManagerEventHandler() { ) // if converge has already begun - restart it immediately if op.engine.TaskQueues.GetMain().Length() > 0 && RemoveCurrentConvergeTasks(op.getConvergeQueues(), logLabels, op.Logger) && op.ConvergeState.Phase != converge.StandBy { - logEntry.Infof("ConvergeModules: global hook dynamic modification detected, restart current converge process (%s)", op.ConvergeState.Phase) + logEntry.Info("ConvergeModules: global hook dynamic modification detected, restart current converge process", + slog.String("phase", string(op.ConvergeState.Phase))) op.engine.TaskQueues.GetMain().AddFirst(convergeTask) op.logTaskAdd(eventLogEntry, "DynamicExtender is updated, put first", convergeTask) } else { // if convege hasn't started - make way for global hooks and etc - logEntry.Infof("ConvergeModules: global hook dynamic modification detected, rerun all modules required") + logEntry.Info("ConvergeModules: global hook dynamic modification detected, rerun all modules required") op.engine.TaskQueues.GetMain().AddLast(convergeTask) } // ConvergeModules may be in progress, Reset converge state. @@ -1128,12 +1146,15 @@ func (op *AddonOperator) StartModuleManagerEventHandler() { switch event.Type { case config.KubeConfigInvalid: op.ModuleManager.SetKubeConfigValid(false) - eventLogEntry.Infof("KubeConfig become invalid") + eventLogEntry.Info("KubeConfig become invalid") case config.KubeConfigChanged: - eventLogEntry.Debugf("ModuleManagerEventHandler-KubeConfigChanged: GlobalSectionChanged %v, ModuleValuesChanged %s, ModuleEnabledStateChanged %s", event.GlobalSectionChanged, event.ModuleValuesChanged, event.ModuleEnabledStateChanged) + eventLogEntry.Debug("ModuleManagerEventHandler-KubeConfigChanged", + slog.Bool("globalSectionChanged", event.GlobalSectionChanged), + slog.Any("moduleValuesChanged", event.ModuleValuesChanged), + slog.Any("moduleEnabledStateChanged", event.ModuleEnabledStateChanged)) if !op.ModuleManager.GetKubeConfigValid() { - eventLogEntry.Infof("KubeConfig become valid") + eventLogEntry.Info("KubeConfig become valid") } // Config is valid now, add task to update ModuleManager state. op.ModuleManager.SetKubeConfigValid(true) @@ -1160,7 +1181,7 @@ func (op *AddonOperator) StartModuleManagerEventHandler() { op.engine.TaskQueues.GetMain().CancelTaskDelay() op.logTaskAdd(eventLogEntry, "KubeConfigExtender is updated, put first", kubeConfigTask) } - eventLogEntry.Infof("Kube config modification detected, ignore until starting first converge") + eventLogEntry.Info("Kube config modification detected, ignore until starting first converge") break } @@ -1176,7 +1197,8 @@ func (op *AddonOperator) StartModuleManagerEventHandler() { ) // if main queue isn't empty and there was another convergeModules task: if op.engine.TaskQueues.GetMain().Length() > 0 && RemoveCurrentConvergeTasks(op.getConvergeQueues(), logLabels, op.Logger) { - logEntry.Infof("ConvergeModules: kube config modification detected, restart current converge process (%s)", op.ConvergeState.Phase) + logEntry.Info("ConvergeModules: kube config modification detected, restart current converge process", + slog.String("phase", string(op.ConvergeState.Phase))) // put ApplyKubeConfig->NewConvergeModulesTask sequence in the beginning of the main queue if kubeConfigTask != nil { op.engine.TaskQueues.GetMain().AddFirst(kubeConfigTask) @@ -1193,7 +1215,7 @@ func (op *AddonOperator) StartModuleManagerEventHandler() { if kubeConfigTask != nil { op.engine.TaskQueues.GetMain().AddFirst(kubeConfigTask) } - logEntry.Infof("ConvergeModules: kube config modification detected, rerun all modules required") + logEntry.Info("ConvergeModules: kube config modification detected, rerun all modules required") op.engine.TaskQueues.GetMain().AddLast(convergeTask) } // ConvergeModules may be in progress, Reset converge state. @@ -1214,7 +1236,9 @@ func (op *AddonOperator) StartModuleManagerEventHandler() { for i := len(reloadTasks) - 1; i >= 0; i-- { op.engine.TaskQueues.GetMain().AddAfter(kubeConfigTask.GetId(), reloadTasks[i]) } - logEntry.Infof("ConvergeModules: kube config modification detected, append %d tasks to rerun modules %+v", len(reloadTasks), modulesToRerun) + logEntry.Info("ConvergeModules: kube config modification detected, append tasks to rerun modules", + slog.Int("count", len(reloadTasks)), + slog.Any("modules", modulesToRerun)) op.logTaskAdd(logEntry, "tail", reloadTasks...) } } @@ -1258,7 +1282,8 @@ func (op *AddonOperator) StartModuleManagerEventHandler() { op.engine.TaskQueues.GetMain().AddLast(newTask.WithQueuedAt(time.Now())) op.logTaskAdd(logEntry, fmt.Sprintf("detected %s, append", additionalDescription), newTask) } else { - eventLogEntry.With("task.flow", "noop").Infof("Detected %s, ModuleRun task already queued", additionalDescription) + eventLogEntry.With("task.flow", "noop").Info("Detected event, ModuleRun task already queued", + slog.String("description", additionalDescription)) } } } @@ -1436,7 +1461,7 @@ func (op *AddonOperator) HandleGlobalHookEnableKubernetesBindings(t sh_task.Task defer trace.StartRegion(context.Background(), "DiscoverHelmReleases").End() logEntry := utils.EnrichLoggerWithLabels(op.Logger, labels) - logEntry.Debugf("Global hook enable kubernetes bindings") + logEntry.Debug("Global hook enable kubernetes bindings") hm := task.HookMetadataAccessor(t) globalHook := op.ModuleManager.GetGlobalHook(hm.HookName) @@ -1501,7 +1526,9 @@ func (op *AddonOperator) HandleGlobalHookEnableKubernetesBindings(t sh_task.Task "queue": t.GetQueueName(), "activation": "OperatorStartup", }) - logEntry.Errorf("Global hook enable kubernetes bindings failed, requeue task to retry after delay. Failed count is %d. Error: %s", t.GetFailureCount()+1, err) + logEntry.Error("Global hook enable kubernetes bindings failed, requeue task to retry after delay.", + slog.Int("count", t.GetFailureCount()+1), + log.Err(err)) t.UpdateFailureMessage(err.Error()) t.WithQueuedAt(queuedAt) res.Status = queue.Fail @@ -1510,13 +1537,14 @@ func (op *AddonOperator) HandleGlobalHookEnableKubernetesBindings(t sh_task.Task // Substitute current task with Synchronization tasks for the main queue. // Other Synchronization tasks are queued into specified queues. // Informers can be started now — their events will be added to the queue tail. - logEntry.Debugf("Global hook enable kubernetes bindings success") + logEntry.Debug("Global hook enable kubernetes bindings success") // "Wait" tasks are queued first for _, tsk := range parallelSyncTasksToWait { q := op.engine.TaskQueues.GetByName(tsk.GetQueueName()) if q == nil { - log.Errorf("Queue %s is not created while run GlobalHookEnableKubernetesBindings task!", tsk.GetQueueName()) + log.Error("Queue is not created while run GlobalHookEnableKubernetesBindings task!", + slog.String("queue", tsk.GetQueueName())) } else { // Skip state creation if WaitForSynchronization is disabled. thm := task.HookMetadataAccessor(tsk) @@ -1529,7 +1557,8 @@ func (op *AddonOperator) HandleGlobalHookEnableKubernetesBindings(t sh_task.Task for _, tsk := range parallelSyncTasks { q := op.engine.TaskQueues.GetByName(tsk.GetQueueName()) if q == nil { - log.Errorf("Queue %s is not created while run GlobalHookEnableKubernetesBindings task!", tsk.GetQueueName()) + log.Error("Queue is not created while run GlobalHookEnableKubernetesBindings task!", + slog.String("queue", tsk.GetQueueName())) } else { q.AddLast(tsk) } @@ -1550,12 +1579,14 @@ func (op *AddonOperator) HandleDiscoverHelmReleases(t sh_task.Task, labels map[s defer trace.StartRegion(context.Background(), "DiscoverHelmReleases").End() logEntry := utils.EnrichLoggerWithLabels(op.Logger, labels) - logEntry.Debugf("Discover Helm releases state") + logEntry.Debug("Discover Helm releases state") state, err := op.ModuleManager.RefreshStateFromHelmReleases(t.GetLogLabels()) if err != nil { res.Status = queue.Fail - logEntry.Errorf("Discover helm releases failed, requeue task to retry after delay. Failed count is %d. Error: %s", t.GetFailureCount()+1, err) + logEntry.Error("Discover helm releases failed, requeue task to retry after delay.", + slog.Int("count", t.GetFailureCount()+1), + log.Err(err)) t.UpdateFailureMessage(err.Error()) t.WithQueuedAt(time.Now()) return @@ -1573,15 +1604,15 @@ func (op *AddonOperator) HandleModulePurge(t sh_task.Task, labels map[string]str defer trace.StartRegion(context.Background(), "ModulePurge").End() logEntry := utils.EnrichLoggerWithLabels(op.Logger, labels) - logEntry.Debugf("Module purge start") + logEntry.Debug("Module purge start") hm := task.HookMetadataAccessor(t) err := op.Helm.NewClient(op.Logger.Named("helm-client"), t.GetLogLabels()).DeleteRelease(hm.ModuleName) if err != nil { // Purge is for unknown modules, just print warning. - logEntry.Warnf("Module purge failed, no retry. Error: %s", err) + logEntry.Warn("Module purge failed, no retry.", log.Err(err)) } else { - logEntry.Debugf("Module purge success") + logEntry.Debug("Module purge success") } status = queue.Success @@ -1598,7 +1629,7 @@ func (op *AddonOperator) HandleModuleDelete(t sh_task.Task, labels map[string]st baseModule := op.ModuleManager.GetModule(hm.ModuleName) logEntry := utils.EnrichLoggerWithLabels(op.Logger, labels) - logEntry.Debugf("Module delete '%s'", hm.ModuleName) + logEntry.Debug("Module delete", slog.String("name", hm.ModuleName)) // Register module hooks to run afterHelmDelete hooks on startup. // It's a noop if registration is done before. @@ -1618,12 +1649,14 @@ func (op *AddonOperator) HandleModuleDelete(t sh_task.Task, labels map[string]st if err != nil { op.engine.MetricStorage.CounterAdd("{PREFIX}module_delete_errors_total", 1.0, map[string]string{"module": hm.ModuleName}) - logEntry.Errorf("Module delete failed, requeue task to retry after delay. Failed count is %d. Error: %s", t.GetFailureCount()+1, err) + logEntry.Error("Module delete failed, requeue task to retry after delay.", + slog.Int("count", t.GetFailureCount()+1), + log.Err(err)) t.UpdateFailureMessage(err.Error()) t.WithQueuedAt(time.Now()) status = queue.Fail } else { - logEntry.Debugf("Module delete success '%s'", hm.ModuleName) + logEntry.Debug("Module delete success", slog.String("name", hm.ModuleName)) status = queue.Success } @@ -1640,11 +1673,11 @@ func (op *AddonOperator) HandleModuleEnsureCRDs(t sh_task.Task, labels map[strin baseModule := op.ModuleManager.GetModule(hm.ModuleName) logEntry := utils.EnrichLoggerWithLabels(op.Logger, labels) - logEntry.Debugf("Module ensureCRDs '%s'", hm.ModuleName) + logEntry.Debug("Module ensureCRDs", slog.String("name", hm.ModuleName)) if appliedGVKs, err := op.EnsureCRDs(baseModule); err != nil { op.ModuleManager.UpdateModuleLastErrorAndNotify(baseModule, err) - logEntry.Errorf("ModuleEnsureCRDs failed. Error: %s", err) + logEntry.Error("ModuleEnsureCRDs failed.", log.Err(err)) t.UpdateFailureMessage(err.Error()) t.WithQueuedAt(time.Now()) res.Status = queue.Fail @@ -1666,7 +1699,8 @@ func (op *AddonOperator) HandleParallelModuleRun(t sh_task.Task, labels map[stri hm := task.HookMetadataAccessor(t) if hm.ParallelRunMetadata == nil { - logEntry.Errorf("Possible bug! Couldn't get task ParallelRunMetadata for a parallel task: %s", hm.EventDescription) + logEntry.Error("Possible bug! Couldn't get task ParallelRunMetadata for a parallel task.", + slog.String("description", hm.EventDescription)) res.Status = queue.Fail return res } @@ -1674,7 +1708,8 @@ func (op *AddonOperator) HandleParallelModuleRun(t sh_task.Task, labels map[stri i := 0 parallelChannel := make(chan parallelQueueEvent) op.parallelTaskChannels.Set(t.GetId(), parallelChannel) - logEntry.Debugf("ParallelModuleRun available parallel event channels %v", op.parallelTaskChannels.channels) + logEntry.Debug("ParallelModuleRun available parallel event channels", + slog.String("channels", fmt.Sprintf("%v", op.parallelTaskChannels.channels))) for moduleName, moduleMetadata := range hm.ParallelRunMetadata.GetModulesMetadata() { queueName := fmt.Sprintf(app.ParallelQueueNamePattern, i%(app.NumberOfParallelQueues-1)) newLogLabels := utils.MergeLabels(labels) @@ -1702,7 +1737,8 @@ L: for { select { case parallelEvent := <-parallelChannel: - logEntry.Debugf("ParallelModuleRun event '%v' received", parallelEvent) + logEntry.Debug("ParallelModuleRun event received", + slog.String("event", fmt.Sprintf("%v", parallelEvent))) if len(parallelEvent.errMsg) != 0 { if tasksErrors[parallelEvent.moduleName] != parallelEvent.errMsg { tasksErrors[parallelEvent.moduleName] = parallelEvent.errMsg @@ -1806,7 +1842,8 @@ func (op *AddonOperator) HandleModuleRun(t sh_task.Task, labels map[string]strin moduleRunErr = op.ModuleManager.RegisterModuleHooks(baseModule, labels) if moduleRunErr == nil { if hm.DoModuleStartup { - logEntry.Debugf("ModuleRun '%s' phase", baseModule.GetPhase()) + logEntry.Debug("ModuleRun phase", + slog.String("phase", string(baseModule.GetPhase()))) treg := trace.StartRegion(context.Background(), "ModuleRun-OnStartup") @@ -1826,7 +1863,7 @@ func (op *AddonOperator) HandleModuleRun(t sh_task.Task, labels map[string]strin } if baseModule.GetPhase() == modules.OnStartupDone { - logEntry.Debugf("ModuleRun '%s' phase", baseModule.GetPhase()) + logEntry.Debug("ModuleRun phase", slog.String("phase", string(baseModule.GetPhase()))) if baseModule.HasKubernetesHooks() { op.ModuleManager.SetModulePhaseAndNotify(baseModule, modules.QueueSynchronizationTasks) } else { @@ -1837,7 +1874,7 @@ func (op *AddonOperator) HandleModuleRun(t sh_task.Task, labels map[string]strin // Note: All hooks should be queued to fill snapshots before proceed to beforeHelm hooks. if baseModule.GetPhase() == modules.QueueSynchronizationTasks { - logEntry.Debugf("ModuleRun '%s' phase", baseModule.GetPhase()) + logEntry.Debug("ModuleRun phase", slog.String("phase", string(baseModule.GetPhase()))) // ModuleHookRun.Synchronization tasks for bindings with the "main" queue. mainSyncTasks := make([]sh_task.Task, 0) @@ -1910,7 +1947,8 @@ func (op *AddonOperator) HandleModuleRun(t sh_task.Task, labels map[string]strin for _, tsk := range parallelSyncTasksToWait { q := op.engine.TaskQueues.GetByName(tsk.GetQueueName()) if q == nil { - logEntry.Errorf("queue %s is not found while EnableKubernetesBindings task", tsk.GetQueueName()) + logEntry.Error("queue is not found while EnableKubernetesBindings task", + slog.String("queue", tsk.GetQueueName())) } else { thm := task.HookMetadataAccessor(tsk) q.AddLast(tsk) @@ -1923,7 +1961,8 @@ func (op *AddonOperator) HandleModuleRun(t sh_task.Task, labels map[string]strin for _, tsk := range parallelSyncTasks { q := op.engine.TaskQueues.GetByName(tsk.GetQueueName()) if q == nil { - logEntry.Errorf("queue %s is not found while EnableKubernetesBindings task", tsk.GetQueueName()) + logEntry.Error("queue is not found while EnableKubernetesBindings task", + slog.String("queue", tsk.GetQueueName())) } else { q.AddLast(tsk) } @@ -1939,7 +1978,7 @@ func (op *AddonOperator) HandleModuleRun(t sh_task.Task, labels map[string]strin op.ModuleManager.SetModulePhaseAndNotify(baseModule, modules.WaitForSynchronization) logEntry.With("module.state", "wait-for-synchronization"). - Debugf("ModuleRun wait for Synchronization") + Debug("ModuleRun wait for Synchronization") } // Put Synchronization tasks for kubernetes hooks before ModuleRun task. @@ -1961,10 +2000,14 @@ func (op *AddonOperator) HandleModuleRun(t sh_task.Task, labels map[string]strin } else { // Debug messages every fifth second: print Synchronization state. if time.Now().UnixNano()%5000000000 == 0 { - logEntry.Debugf("ModuleRun wait Synchronization state: moduleStartup:%v syncNeeded:%v syncQueued:%v syncDone:%v", hm.DoModuleStartup, baseModule.SynchronizationNeeded(), baseModule.Synchronization().HasQueued(), baseModule.Synchronization().IsCompleted()) + logEntry.Debug("ModuleRun wait Synchronization state", + slog.Bool("moduleStartup", hm.DoModuleStartup), + slog.Bool("syncNeeded", baseModule.SynchronizationNeeded()), + slog.Bool("syncQueued", baseModule.Synchronization().HasQueued()), + slog.Bool("syncDone", baseModule.Synchronization().IsCompleted())) baseModule.Synchronization().DebugDumpState(logEntry) } - logEntry.Debugf("Synchronization not completed, keep ModuleRun task in repeat mode") + logEntry.Debug("Synchronization not completed, keep ModuleRun task in repeat mode") t.WithQueuedAt(time.Now()) res.Status = queue.Repeat return @@ -1973,7 +2016,7 @@ func (op *AddonOperator) HandleModuleRun(t sh_task.Task, labels map[string]strin // Enable schedule events once at module start. if baseModule.GetPhase() == modules.EnableScheduleBindings { - logEntry.Debugf("ModuleRun '%s' phase", baseModule.GetPhase()) + logEntry.Debug("ModuleRun phase", slog.String("phase", string(baseModule.GetPhase()))) op.ModuleManager.EnableModuleScheduleBindings(hm.ModuleName) op.ModuleManager.SetModulePhaseAndNotify(baseModule, modules.CanRunHelm) @@ -1981,7 +2024,7 @@ func (op *AddonOperator) HandleModuleRun(t sh_task.Task, labels map[string]strin // Module start is done, module is ready to run hooks and helm chart. if baseModule.GetPhase() == modules.CanRunHelm { - logEntry.Debugf("ModuleRun '%s' phase", baseModule.GetPhase()) + logEntry.Debug("ModuleRun phase", slog.String("phase", string(baseModule.GetPhase()))) // run beforeHelm, helm, afterHelm valuesChanged, moduleRunErr = op.ModuleManager.RunModule(baseModule.Name, t.GetLogLabels()) } @@ -1989,14 +2032,17 @@ func (op *AddonOperator) HandleModuleRun(t sh_task.Task, labels map[string]strin op.ModuleManager.UpdateModuleLastErrorAndNotify(baseModule, moduleRunErr) if moduleRunErr != nil { res.Status = queue.Fail - logEntry.Errorf("ModuleRun failed in phase '%s'. Requeue task to retry after delay. Failed count is %d. Error: %s", baseModule.GetPhase(), t.GetFailureCount()+1, moduleRunErr) + logEntry.Error("ModuleRun failed. Requeue task to retry after delay.", + slog.String("phase", string(baseModule.GetPhase())), + slog.Int("count", t.GetFailureCount()+1), + log.Err(moduleRunErr)) op.engine.MetricStorage.CounterAdd("{PREFIX}module_run_errors_total", 1.0, map[string]string{"module": hm.ModuleName}) t.UpdateFailureMessage(moduleRunErr.Error()) t.WithQueuedAt(time.Now()) } else { res.Status = queue.Success if valuesChanged { - logEntry.Infof("ModuleRun success, values changed, restart module") + logEntry.Info("ModuleRun success, values changed, restart module") // One of afterHelm hooks changes values, run ModuleRun again: copy task, but disable startup hooks. hm.DoModuleStartup = false hm.EventDescription = "AfterHelm-Hooks-Change-Values" @@ -2010,7 +2056,7 @@ func (op *AddonOperator) HandleModuleRun(t sh_task.Task, labels map[string]strin res.AfterTasks = []sh_task.Task{newTask.WithQueuedAt(time.Now())} op.logTaskAdd(logEntry, "after", res.AfterTasks...) } else { - logEntry.Infof("ModuleRun success, module is ready") + logEntry.Info("ModuleRun success, module is ready") } } return @@ -2085,7 +2131,10 @@ func (op *AddonOperator) HandleModuleHookRun(t sh_task.Task, labels map[string]s } // Task 'tsk' will be combined, so remove it from the SynchronizationState. if thm.IsSynchronization() { - logEntry.Debugf("Synchronization task for %s/%s is combined, mark it as Done: id=%s", thm.HookName, thm.Binding, thm.KubernetesBindingId) + logEntry.Debug("Synchronization task is combined, mark it as Done", + slog.String("name", thm.HookName), + slog.String("binding", thm.Binding), + slog.String("id", thm.KubernetesBindingId)) baseModule.Synchronization().DoneForBinding(thm.KubernetesBindingId) } return false // do not stop combine process on this task @@ -2097,7 +2146,7 @@ func (op *AddonOperator) HandleModuleHookRun(t sh_task.Task, labels map[string]s if len(combineResult.MonitorIDs) > 0 { hm.MonitorIDs = append(hm.MonitorIDs, combineResult.MonitorIDs...) } - logEntry.Debugf("Got monitorIDs: %+v", hm.MonitorIDs) + logEntry.Debug("Got monitorIDs", slog.Any("monitorIDs", hm.MonitorIDs)) t.UpdateMetadata(hm) } } @@ -2119,12 +2168,14 @@ func (op *AddonOperator) HandleModuleHookRun(t sh_task.Task, labels map[string]s if err != nil { if hm.AllowFailure { allowed = 1.0 - logEntry.Infof("Module hook failed, but allowed to fail. Error: %v", err) + logEntry.Info("Module hook failed, but allowed to fail.", log.Err(err)) res.Status = queue.Success op.ModuleManager.UpdateModuleHookStatusAndNotify(baseModule, hm.HookName, nil) } else { errors = 1.0 - logEntry.Errorf("Module hook failed, requeue task to retry after delay. Failed count is %d. Error: %s", t.GetFailureCount()+1, err) + logEntry.Error("Module hook failed, requeue task to retry after delay.", + slog.Int("count", t.GetFailureCount()+1), + log.Err(err)) t.UpdateFailureMessage(err.Error()) t.WithQueuedAt(time.Now()) res.Status = queue.Fail @@ -2132,7 +2183,7 @@ func (op *AddonOperator) HandleModuleHookRun(t sh_task.Task, labels map[string]s } } else { success = 1.0 - logEntry.Debugf("Module hook success '%s'", hm.HookName) + logEntry.Debug("Module hook success", slog.String("name", hm.HookName)) res.Status = queue.Success op.ModuleManager.UpdateModuleHookStatusAndNotify(baseModule, hm.HookName, nil) @@ -2142,7 +2193,7 @@ func (op *AddonOperator) HandleModuleHookRun(t sh_task.Task, labels map[string]s switch hm.BindingType { case htypes.Schedule: if beforeChecksum != afterChecksum { - logEntry.Infof("Module hook changed values, will restart ModuleRun.") + logEntry.Info("Module hook changed values, will restart ModuleRun.") reloadModule = true eventDescription = "Schedule-Change-ModuleValues" } @@ -2150,9 +2201,9 @@ func (op *AddonOperator) HandleModuleHookRun(t sh_task.Task, labels map[string]s // Do not reload module on changes during Synchronization. if beforeChecksum != afterChecksum { if hm.IsSynchronization() { - logEntry.Infof("Module hook changed values, but restart ModuleRun is ignored for the Synchronization task.") + logEntry.Info("Module hook changed values, but restart ModuleRun is ignored for the Synchronization task.") } else { - logEntry.Infof("Module hook changed values, will restart ModuleRun.") + logEntry.Info("Module hook changed values, will restart ModuleRun.") reloadModule = true eventDescription = "Kubernetes-Change-ModuleValues" } @@ -2189,7 +2240,7 @@ func (op *AddonOperator) HandleModuleHookRun(t sh_task.Task, labels map[string]s op.engine.TaskQueues.GetMain().AddLast(newTask.WithQueuedAt(time.Now())) op.logTaskAdd(logEntry, "module values are changed, append", newTask) } else { - logEntry.With("task.flow", "noop").Infof("module values are changed, ModuleRun task already queued") + logEntry.With("task.flow", "noop").Info("module values are changed, ModuleRun task already queued") } } } @@ -2245,13 +2296,13 @@ func (op *AddonOperator) HandleGlobalHookRun(t sh_task.Task, labels map[string]s if isSynchronization { // Synchronization is not a part of v0 contract, skip hook execution. if taskHook.GetHookConfig().Version == "v0" { - logEntry.Infof("Execute on Synchronization ignored for v0 hooks") + logEntry.Info("Execute on Synchronization ignored for v0 hooks") shouldRunHook = false res.Status = queue.Success } // Check for "executeOnSynchronization: false". if !hm.ExecuteOnSynchronization { - logEntry.Infof("Execute on Synchronization disabled in hook config: ExecuteOnSynchronization=false") + logEntry.Info("Execute on Synchronization disabled in hook config: ExecuteOnSynchronization=false") shouldRunHook = false res.Status = queue.Success } @@ -2273,7 +2324,10 @@ func (op *AddonOperator) HandleGlobalHookRun(t sh_task.Task, labels map[string]s } // Task 'tsk' will be combined, so remove it from the GlobalSynchronizationState. if thm.IsSynchronization() { - logEntry.Debugf("Synchronization task for %s/%s is combined, mark it as Done: id=%s", thm.HookName, thm.Binding, thm.KubernetesBindingId) + logEntry.Debug("Synchronization task is combined, mark it as Done", + slog.String("name", thm.HookName), + slog.String("binding", thm.Binding), + slog.String("id", thm.KubernetesBindingId)) op.ModuleManager.GlobalSynchronizationState().DoneForBinding(thm.KubernetesBindingId) } return false // Combine tsk. @@ -2283,10 +2337,13 @@ func (op *AddonOperator) HandleGlobalHookRun(t sh_task.Task, labels map[string]s hm.BindingContext = combineResult.BindingContexts // Extra monitor IDs can be returned if several Synchronization binding contexts are combined. if len(combineResult.MonitorIDs) > 0 { - logEntry.Debugf("Task monitorID: %s, combined monitorIDs: %+v", hm.MonitorIDs, combineResult.MonitorIDs) + logEntry.Debug("Task monitorID. Combined monitorIDs.", + slog.Any("monitorIDs", hm.MonitorIDs), + slog.Any("combinedMonitorIDs", combineResult.MonitorIDs)) hm.MonitorIDs = combineResult.MonitorIDs } - logEntry.Debugf("Got monitorIDs: %+v", hm.MonitorIDs) + logEntry.Debug("Got monitorIDs", + slog.Any("monitorIDs", hm.MonitorIDs)) t.UpdateMetadata(hm) } } @@ -2295,7 +2352,7 @@ func (op *AddonOperator) HandleGlobalHookRun(t sh_task.Task, labels map[string]s // op.HelmResourcesManager.PauseMonitors() if shouldRunHook { - logEntry.Debugf("Global hook run") + logEntry.Debug("Global hook run") errors := 0.0 success := 0.0 @@ -2306,11 +2363,13 @@ func (op *AddonOperator) HandleGlobalHookRun(t sh_task.Task, labels map[string]s if err != nil { if hm.AllowFailure { allowed = 1.0 - logEntry.Infof("Global hook failed, but allowed to fail. Error: %v", err) + logEntry.Info("Global hook failed, but allowed to fail.", log.Err(err)) res.Status = queue.Success } else { errors = 1.0 - logEntry.Errorf("Global hook failed, requeue task to retry after delay. Failed count is %d. Error: %s", t.GetFailureCount()+1, err) + logEntry.Error("Global hook failed, requeue task to retry after delay.", + slog.Int("count", t.GetFailureCount()+1), + log.Err(err)) t.UpdateFailureMessage(err.Error()) t.WithQueuedAt(time.Now()) res.Status = queue.Fail @@ -2318,7 +2377,10 @@ func (op *AddonOperator) HandleGlobalHookRun(t sh_task.Task, labels map[string]s } else { // Calculate new checksum of *Enabled values. success = 1.0 - logEntry.Debugf("GlobalHookRun success, checksums: before=%s after=%s saved=%s", beforeChecksum, afterChecksum, hm.ValuesChecksum) + logEntry.Debug("GlobalHookRun success", + slog.String("beforeChecksum", beforeChecksum), + slog.String("afterChecksum", afterChecksum), + slog.String("savedChecksum", hm.ValuesChecksum)) res.Status = queue.Success reloadAll := false @@ -2326,28 +2388,28 @@ func (op *AddonOperator) HandleGlobalHookRun(t sh_task.Task, labels map[string]s switch hm.BindingType { case htypes.Schedule: if beforeChecksum != afterChecksum { - logEntry.Infof("Global hook changed values, will run ReloadAll.") + logEntry.Info("Global hook changed values, will run ReloadAll.") reloadAll = true eventDescription = "Schedule-Change-GlobalValues" } case htypes.OnKubernetesEvent: if beforeChecksum != afterChecksum { if hm.ReloadAllOnValuesChanges { - logEntry.Infof("Global hook changed values, will run ReloadAll.") + logEntry.Info("Global hook changed values, will run ReloadAll.") reloadAll = true eventDescription = "Kubernetes-Change-GlobalValues" } else { - logEntry.Infof("Global hook changed values, but ReloadAll ignored for the Synchronization task.") + logEntry.Info("Global hook changed values, but ReloadAll ignored for the Synchronization task.") } } case hookTypes.AfterAll: if !hm.LastAfterAllHook && afterChecksum != beforeChecksum { - logEntry.Infof("Global hook changed values, but ReloadAll ignored: more AfterAll hooks to execute.") + logEntry.Info("Global hook changed values, but ReloadAll ignored: more AfterAll hooks to execute.") } // values are changed when afterAll hooks are executed if hm.LastAfterAllHook && afterChecksum != hm.ValuesChecksum { - logEntry.Infof("Global values changed by AfterAll hooks, will run ReloadAll.") + logEntry.Info("Global values changed by AfterAll hooks, will run ReloadAll.") reloadAll = true eventDescription = "AfterAll-Hooks-Change-GlobalValues" } @@ -2357,7 +2419,7 @@ func (op *AddonOperator) HandleGlobalHookRun(t sh_task.Task, labels map[string]s // if helm3lib is in use - reinit helm action configuration to update helm capabilities (newly available apiVersions and resoruce kinds) if op.Helm.ClientType == helm.Helm3Lib { if err := helm3lib.ReinitActionConfig(op.Logger.Named("helm3-client")); err != nil { - logEntry.Errorf("Couldn't reinitialize helm3lib action configuration: %s", err) + logEntry.Error("Couldn't reinitialize helm3lib action configuration", log.Err(err)) t.UpdateFailureMessage(err.Error()) t.WithQueuedAt(time.Now()) res.Status = queue.Fail @@ -2400,7 +2462,7 @@ func (op *AddonOperator) HandleGlobalHookRun(t sh_task.Task, labels map[string]s if isSynchronization && res.Status == queue.Success { op.ModuleManager.GlobalSynchronizationState().DoneForBinding(hm.KubernetesBindingId) // Unlock Kubernetes events for all monitors when Synchronization task is done. - logEntry.Debugf("Synchronization done, unlock Kubernetes events") + logEntry.Debug("Synchronization done, unlock Kubernetes events") for _, monitorID := range hm.MonitorIDs { taskHook.GetHookController().UnlockKubernetesEventsFor(monitorID) } @@ -2445,7 +2507,8 @@ func (op *AddonOperator) CreateConvergeModulesTasks(state *module_manager.Module queuedAt := time.Now() // Add ModuleDelete tasks to delete helm releases of disabled modules. - log.Debugf("The following modules are going to be disabled: %v", state.ModulesToDisable) + log.Debug("The following modules are going to be disabled", + slog.Any("modules", state.ModulesToDisable)) for _, moduleName := range state.ModulesToDisable { ev := events.ModuleEvent{ ModuleName: moduleName, @@ -2468,7 +2531,8 @@ func (op *AddonOperator) CreateConvergeModulesTasks(state *module_manager.Module // Add ModuleRun tasks to install or reload enabled modules. newlyEnabled := utils.ListToMapStringStruct(state.ModulesToEnable) - log.Debugf("The following modules are going to be enabled/rerun: %v", state.AllEnabledModulesByOrder) + log.Debug("The following modules are going to be enabled/rerun", + slog.String("modules", fmt.Sprintf("%v", state.AllEnabledModulesByOrder))) for _, modules := range state.AllEnabledModulesByOrder { newLogLabels := utils.MergeLabels(logLabels) @@ -2550,7 +2614,8 @@ func (op *AddonOperator) CreateConvergeModulesTasks(state *module_manager.Module modulesTasks = append(modulesTasks, newTask.WithQueuedAt(queuedAt)) default: - log.Errorf("Invalid ModulesState %v", state) + log.Error("Invalid ModulesState", + slog.String("state", fmt.Sprintf("%v", state))) } } // as resultingTasks contains new ensureCRDsTasks we invalidate @@ -2614,7 +2679,8 @@ func (op *AddonOperator) CheckConvergeStatus(t sh_task.Task) { // Report modules left to process. if convergeTasks > 0 && (t.GetType() == task.ModuleRun || t.GetType() == task.ModuleDelete) { moduleTasks := ConvergeModulesInQueue(op.engine.TaskQueues.GetMain()) - log.Infof("Converge modules in progress: %d modules left to process in queue 'main'", moduleTasks) + log.Info("Converge modules in progress", + slog.Int("count", moduleTasks)) } } @@ -2632,7 +2698,7 @@ func (op *AddonOperator) UpdateFirstConvergeStatus(convergeTasks int) { case converge.FirstStarted: // Switch to 'done' state after first converge is started and when no 'converge' tasks left in the queue. if convergeTasks == 0 { - log.Infof("First converge is finished. Operator is ready now.") + log.Info("First converge is finished. Operator is ready now.") op.ConvergeState.SetFirstRunPhase(converge.FirstDone) } } diff --git c/pkg/addon-operator/operator_test.go i/pkg/addon-operator/operator_test.go index a1ffaa6..7ad550d 100644 --- c/pkg/addon-operator/operator_test.go +++ i/pkg/addon-operator/operator_test.go @@ -2,6 +2,7 @@ package addon_operator import ( "context" + "log/slog" "os" "path/filepath" "strings" @@ -513,7 +514,8 @@ func Test_HandleConvergeModules_global_changed(t *testing.T) { g.Eventually(convergeDone(op), "30s", "200ms").Should(BeTrue()) - log.Infof("Converge done, got %d tasks in history", len(taskHandleHistory)) + log.Info("Converge done, got tasks in history", + slog.Int("count", len(taskHandleHistory))) // Save current history length to ignore first converge tasks later. ignoreTasksCount := len(taskHandleHistory) @@ -534,7 +536,8 @@ func Test_HandleConvergeModules_global_changed(t *testing.T) { g.Expect(cmPatched.Data).Should(HaveKey("global")) g.Expect(cmPatched.Data["global"]).Should(Equal("param: newValue")) - log.Infof("ConfigMap patched, got %d tasks in history", len(taskHandleHistory)) + log.Info("ConfigMap patched, got tasks in history", + slog.Int("count", len(taskHandleHistory))) // Expect ConvergeModules appears in queue. g.Eventually(func() bool { diff --git c/pkg/addon-operator/queue.go i/pkg/addon-operator/queue.go index e365f94..4445113 100644 --- c/pkg/addon-operator/queue.go +++ i/pkg/addon-operator/queue.go @@ -1,6 +1,8 @@ package addon_operator import ( + "log/slog" + "github.com/deckhouse/deckhouse/pkg/log" "github.com/flant/addon-operator/pkg/addon-operator/converge" @@ -114,13 +116,21 @@ func RemoveCurrentConvergeTasks(convergeQueues []*queue.TaskQueue, logLabels map case task.ParallelModuleRun: if hm.ParallelRunMetadata == nil || hm.ParallelRunMetadata.CancelF == nil { - logEntry.Warnf("Couldn't get parallelRun metadata for the parallel task of type: %s, module: %s, description: %s, from queue %s", t.GetType(), hm.ModuleName, hm.EventDescription, queue.Name) + logEntry.Warn("Couldn't get parallelRun metadata for the parallel task", + slog.String("type", string(t.GetType())), + slog.String("module", hm.ModuleName), + slog.String("description", hm.EventDescription), + slog.String("queue", queue.Name)) } else { // cancel parallel task context hm.ParallelRunMetadata.CancelF() } } - logEntry.Debugf("Drained converge task of type: %s, module: %s, description: %s, from queue %s", t.GetType(), hm.ModuleName, hm.EventDescription, queue.Name) + logEntry.Debug("Drained converge task", + slog.String("type", string(t.GetType())), + slog.String("module", hm.ModuleName), + slog.String("description", hm.EventDescription), + slog.String("queue", queue.Name)) return false } return true @@ -164,7 +174,10 @@ func RemoveCurrentConvergeTasksFromId(q *queue.TaskQueue, afterId string, logLab stop = true } hm := task.HookMetadataAccessor(t) - logEntry.Debugf("Drained converge task of type: %s, module: %s, description: %s", t.GetType(), hm.ModuleName, hm.EventDescription) + logEntry.Debug("Drained converge task", + slog.String("type", string(t.GetType())), + slog.String("module", hm.ModuleName), + slog.String("description", hm.EventDescription)) return false } return true @@ -198,7 +211,9 @@ func RemoveAdjacentConvergeModules(q *queue.TaskQueue, afterId string, logLabels // Remove ConvergeModules after current. if t.GetType() == task.ConvergeModules { hm := task.HookMetadataAccessor(t) - logEntry.Debugf("Drained adjacent ConvergeModules task of type: %s, description: %s", t.GetType(), hm.EventDescription) + logEntry.Debug("Drained adjacent ConvergeModules task", + slog.String("type", string(t.GetType())), + slog.String("description", hm.EventDescription)) return false } diff --git c/pkg/helm/helm.go i/pkg/helm/helm.go index e08a9da..4c5a1e1 100644 --- c/pkg/helm/helm.go +++ i/pkg/helm/helm.go @@ -1,6 +1,7 @@ package helm import ( + "log/slog" "time" "github.com/deckhouse/deckhouse/pkg/log" @@ -51,7 +52,7 @@ func InitHelmClientFactory(helmopts *Options, extraLabels map[string]string) (*C }, helmopts.Logger, extraLabels) case Helm3: - log.Infof("Helm 3 detected (path is '%s')", helm3.Helm3Path) + log.Info("Helm 3 detected", slog.String("path", helm3.Helm3Path)) // Use helm3 client. factory.ClientType = Helm3 factory.NewClientFn = helm3.NewClient diff --git c/pkg/helm/helm3/helm3.go i/pkg/helm/helm3/helm3.go index 8eb59b8..8ec1a0a 100644 --- c/pkg/helm/helm3/helm3.go +++ i/pkg/helm/helm3/helm3.go @@ -3,6 +3,7 @@ package helm3 import ( "bytes" "fmt" + "log/slog" "os/exec" "sort" "strings" @@ -87,7 +88,7 @@ func (h *Helm3Client) initAndVersion() error { } stdout = strings.Join([]string{stdout, stderr}, "\n") stdout = strings.ReplaceAll(stdout, "\n", " ") - log.Infof("Helm 3 version: %s", stdout) + log.Info("Helm 3 version", slog.String("version", stdout)) return nil } @@ -161,12 +162,20 @@ func (h *Helm3Client) UpgradeRelease(releaseName string, chart string, valuesPat args = append(args, setValue) } - h.Logger.Infof("Running helm upgrade for release '%s' with chart '%s' in namespace '%s' ...", releaseName, chart, namespace) + h.Logger.Info("Running helm upgrade for release ...", + slog.String("release", releaseName), + slog.String("chart", chart), + slog.String("namespace", namespace)) stdout, stderr, err := h.cmd(args...) if err != nil { return fmt.Errorf("helm upgrade failed: %s:\n%s %s", err, stdout, stderr) } - h.Logger.Infof("Helm upgrade for release '%s' with chart '%s' in namespace '%s' successful:\n%s\n%s", releaseName, chart, namespace, stdout, stderr) + h.Logger.Info("Helm upgrade for release successful", + slog.String("release", releaseName), + slog.String("chart", chart), + slog.String("namespace", namespace), + slog.String("stdout", stdout), + slog.String("stderr", stderr)) return nil } @@ -191,7 +200,7 @@ func (h *Helm3Client) GetReleaseValues(releaseName string) (utils.Values, error) } func (h *Helm3Client) DeleteRelease(releaseName string) (err error) { - h.Logger.Debugf("helm release '%s': execute helm uninstall", releaseName) + h.Logger.Debug("helm release: execute helm uninstall", slog.String("release", releaseName)) args := []string{ "uninstall", releaseName, @@ -202,7 +211,7 @@ func (h *Helm3Client) DeleteRelease(releaseName string) (err error) { return fmt.Errorf("helm uninstall %s invocation error: %v\n%v %v", releaseName, err, stdout, stderr) } - h.Logger.Debugf("helm release %s deleted", releaseName) + h.Logger.Debug("helm release deleted", slog.String("release", releaseName)) return } @@ -230,9 +239,9 @@ func (h *Helm3Client) ListReleasesNames() ([]string, error) { return nil, fmt.Errorf("helm list failed: %v\n%s %s", err, stdout, stderr) } - list := []struct { + var list []struct { Name string `json:"name"` - }{} + } if err := k8syaml.Unmarshal([]byte(stdout), &list); err != nil { return nil, fmt.Errorf("helm list returned invalid json: %v", err) @@ -278,12 +287,15 @@ func (h *Helm3Client) Render(releaseName string, chart string, valuesPaths []str args = append(args, setValue) } - h.Logger.Debugf("Render helm templates for chart '%s' in namespace '%s' ...", chart, namespace) + h.Logger.Debug("Render helm templates for chart ...", + slog.String("chart", chart), + slog.String("namespace", namespace)) stdout, stderr, err := h.cmd(args...) if err != nil { return "", fmt.Errorf("helm upgrade failed: %s:\n%s %s", err, stdout, stderr) } - h.Logger.Infof("Render helm templates for chart '%s' was successful", chart) + h.Logger.Info("Render helm templates for chart was successful", + slog.String("chart", chart)) return stdout, nil } diff --git c/pkg/helm/helm3lib/helm3lib.go i/pkg/helm/helm3lib/helm3lib.go index bacfe50..c01115f 100644 --- c/pkg/helm/helm3lib/helm3lib.go +++ i/pkg/helm/helm3lib/helm3lib.go @@ -2,7 +2,9 @@ package helm3lib import ( "context" + "errors" "fmt" + "log/slog" "os" "sort" "strconv" @@ -18,7 +20,7 @@ import ( "helm.sh/helm/v3/pkg/releaseutil" "helm.sh/helm/v3/pkg/storage" "helm.sh/helm/v3/pkg/storage/driver" - "k8s.io/apimachinery/pkg/api/errors" + apierrors "k8s.io/apimachinery/pkg/api/errors" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" "k8s.io/cli-runtime/pkg/genericclioptions" "k8s.io/client-go/rest" @@ -125,7 +127,7 @@ func (h *LibClient) actionConfigInit() error { // If env is empty - default storage backend ('secrets') will be used helmDriver := os.Getenv("HELM_DRIVER") - err := ac.Init(getter, options.Namespace, helmDriver, h.Logger.Debugf) + err := ac.Init(getter, options.Namespace, helmDriver, h.Logger.Debug) if err != nil { return fmt.Errorf("init helm action config: %v", err) } @@ -141,7 +143,7 @@ func (h *LibClient) initAndVersion() error { return err } - log.Infof("Helm 3 version: %s", chartutil.DefaultCapabilities.HelmVersion.Version) + log.Info("Helm 3 version", slog.String("version", chartutil.DefaultCapabilities.HelmVersion.Version)) return nil } @@ -154,7 +156,7 @@ func (h *LibClient) LastReleaseStatus(releaseName string) (revision string, stat // return nil, errors.Errorf("no revision for release %q", name) // } // that's why we also check string representation - if err == driver.ErrReleaseNotFound || strings.HasPrefix(err.Error(), "no revision for release") { + if errors.Is(err, driver.ErrReleaseNotFound) || strings.HasPrefix(err.Error(), "no revision for release") { return "0", "", fmt.Errorf("release '%s' not found\n", releaseName) } return "", "", err @@ -173,7 +175,7 @@ func (h *LibClient) UpgradeRelease(releaseName string, chartName string, valuesP } return h.upgradeRelease(releaseName, chartName, valuesPaths, setValues, namespace) } - h.Logger.Debugf("helm release %s upgraded", releaseName) + h.Logger.Debug("helm release upgraded", slog.String("version", releaseName)) return nil } @@ -217,12 +219,15 @@ func (h *LibClient) upgradeRelease(releaseName string, chartName string, valuesP resultValues = chartutil.CoalesceTables(resultValues, m) } - h.Logger.Infof("Running helm upgrade for release '%s' with chart '%s' in namespace '%s' ...", releaseName, chartName, namespace) + h.Logger.Info("Running helm upgrade for release", + slog.String("release", releaseName), + slog.String("chart", chartName), + slog.String("namespace", namespace)) histClient := action.NewHistory(actionConfig) // Max is not working!!! Sort the final of releases by your own // histClient.Max = 1 releases, err := histClient.Run(releaseName) - if err == driver.ErrReleaseNotFound { + if errors.Is(err, driver.ErrReleaseNotFound) { instClient := action.NewInstall(actionConfig) if namespace != "" { instClient.Namespace = namespace @@ -237,7 +242,7 @@ func (h *LibClient) upgradeRelease(releaseName string, chartName string, valuesP _, err = instClient.Run(chart, resultValues) return err } - h.Logger.Debugf("%d old releases found", len(releases)) + h.Logger.Debug("old releases found", slog.Int("count", len(releases))) if len(releases) > 0 { // https://github.com/fluxcd/helm-controller/issues/149 // looking through this issue you can find the common error: another operation (install/upgrade/rollback) is in progress @@ -245,7 +250,10 @@ func (h *LibClient) upgradeRelease(releaseName string, chartName string, valuesP releaseutil.Reverse(releases, releaseutil.SortByRevision) latestRelease := releases[0] nsReleaseName := fmt.Sprintf("%s/%s", latestRelease.Namespace, latestRelease.Name) - h.Logger.Debugf("Latest release '%s': revision: %d has status: %s", nsReleaseName, latestRelease.Version, latestRelease.Info.Status) + h.Logger.Debug("Latest release info", + slog.String("release", nsReleaseName), + slog.Int("version", latestRelease.Version), + slog.String("status", string(latestRelease.Info.Status))) if latestRelease.Info.Status.IsPending() { objectName := fmt.Sprintf("%s.%s.v%d", storage.HelmStorageType, latestRelease.Name, latestRelease.Version) kubeClient, err := actionConfig.KubernetesClientSet() @@ -255,24 +263,36 @@ func (h *LibClient) upgradeRelease(releaseName string, chartName string, valuesP // switch between storage types (memory, sql, secrets, configmaps) - with secrets and configmaps we can deal a bit more straightforward than doing a rollback switch actionConfig.Releases.Name() { case driver.ConfigMapsDriverName: - h.Logger.Debugf("ConfigMap for helm revision %d of release %s in status %s, driver %s: will be deleted", latestRelease.Version, nsReleaseName, latestRelease.Info.Status, driver.ConfigMapsDriverName) + h.Logger.Debug("ConfigMap for helm", + slog.Int("version", latestRelease.Version), + slog.String("release", nsReleaseName), + slog.String("status", string(latestRelease.Info.Status)), + slog.String("driver", driver.ConfigMapsDriverName)) err := kubeClient.CoreV1().ConfigMaps(latestRelease.Namespace).Delete(context.TODO(), objectName, metav1.DeleteOptions{}) - if err != nil && !errors.IsNotFound(err) { + if err != nil && !apierrors.IsNotFound(err) { return fmt.Errorf("couldn't delete configmap %s of release %s: %w", objectName, nsReleaseName, err) } - h.Logger.Debugf("ConfigMap %s was deleted", objectName) + h.Logger.Debug("ConfigMap was deleted", slog.String("name", objectName)) case driver.SecretsDriverName: - h.Logger.Debugf("Secret for helm revision %d of release %s in status %s, driver %s: will be deleted", latestRelease.Version, nsReleaseName, latestRelease.Info.Status, driver.SecretsDriverName) + h.Logger.Debug("Secret for helm will be deleted", + slog.Int("version", latestRelease.Version), + slog.String("release", nsReleaseName), + slog.String("status", string(latestRelease.Info.Status)), + slog.String("driver", driver.ConfigMapsDriverName)) err := kubeClient.CoreV1().Secrets(latestRelease.Namespace).Delete(context.TODO(), objectName, metav1.DeleteOptions{}) - if err != nil && !errors.IsNotFound(err) { + if err != nil && !apierrors.IsNotFound(err) { return fmt.Errorf("couldn't delete secret %s of release %s: %w", objectName, nsReleaseName, err) } - h.Logger.Debugf("Secret %s was deleted", objectName) + h.Logger.Debug("Secret was deleted", slog.String("name", objectName)) default: // memory and sql storages a bit more trickier - doing a rollback is justified - h.Logger.Debugf("Helm revision %d of release %s in status %s, driver %s: will be rolledback", latestRelease.Version, nsReleaseName, latestRelease.Info.Status, actionConfig.Releases.Name()) + h.Logger.Debug("Helm will be rollback", + slog.Int("version", latestRelease.Version), + slog.String("release", nsReleaseName), + slog.String("status", string(latestRelease.Info.Status)), + slog.String("driver", driver.ConfigMapsDriverName)) h.rollbackLatestRelease(releases) } } @@ -282,7 +302,10 @@ func (h *LibClient) upgradeRelease(releaseName string, chartName string, valuesP if err != nil { return fmt.Errorf("helm upgrade failed: %s\n", err) } - h.Logger.Infof("Helm upgrade for release '%s' with chart '%s' in namespace '%s' successful", releaseName, chartName, namespace) + h.Logger.Info("Helm upgrade successful", + slog.String("release", releaseName), + slog.String("chart", chartName), + slog.String("namespace", namespace)) return nil } @@ -291,14 +314,16 @@ func (h *LibClient) rollbackLatestRelease(releases []*release.Release) { latestRelease := releases[0] nsReleaseName := fmt.Sprintf("%s/%s", latestRelease.Namespace, latestRelease.Name) - h.Logger.Infof("Trying to rollback '%s'", nsReleaseName) + h.Logger.Info("Trying to rollback", slog.String("release", nsReleaseName)) if latestRelease.Version == 1 || options.HistoryMax == 1 || len(releases) == 1 { rb := action.NewUninstall(actionConfig) rb.KeepHistory = false _, err := rb.Run(latestRelease.Name) if err != nil { - h.Logger.Warnf("Failed to uninstall pending release %s: %s", nsReleaseName, err) + h.Logger.Warn("Failed to uninstall pending release", + slog.String("release", nsReleaseName), + lo…
Signed-off-by: Evsyukov Denis <denis.evsyukov@flant.com>
fb7222f
to
4b05d01
Compare
Signed-off-by: Evsyukov Denis <denis.evsyukov@flant.com>
4b05d01
to
93bd407
Compare
Overview
Fixed: #524
What this PR does / why we need it
Just replace deprecated logger methods
Special notes for your reviewer
nope