Commit
This commit does not belong to any branch on this repository, and may belong to a fork outside of the repository.
feat: replace deprecated logger methods
Signed-off-by: Evsyukov Denis <[email protected]> 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…
- Loading branch information
