replace deprecated logger methods (#702)

Signed-off-by: Evsyukov Denis <denis.evsyukov@flant.com>

.golangci.yaml

@@ -39,11 +39,6 @@ linters-settings:
     local-prefixes: github.com/flant/
   nolintlint:
     allow-unused: true
-  # 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

pkg/app/log.go

@@ -2,6 +2,7 @@ package app
 
 import (
 	"fmt"
+	"log/slog"
 	"strings"
 	"time"
 
@@ -70,7 +71,7 @@ func SetupLogging(runtimeConfig *config.Config, logger *log.Logger) {
 		fmt.Sprintf("Global log level. Default duration for debug level is %s", ForcedDurationForDebugLevel),
 		strings.ToLower(LogLevel),
 		func(_ string, newValue string) error {
-			logger.Infof("Set log level to '%s'", newValue)
+			logger.Info("Change log level", slog.String("value", newValue))
 			log.SetDefaultLevel(log.LogLevelFromStr(newValue))
 			return nil
 		}, func(_ string, newValue string) time.Duration {

pkg/debug/server.go

@@ -4,6 +4,7 @@ import (
 	"encoding/json"
 	"fmt"
 	"io"
+	"log/slog"
 	"net"
 	"net/http"
 	"os"
@@ -67,19 +68,19 @@ func (s *Server) Init() error {
 		return fmt.Errorf("Debug HTTP server fail to listen on '%s': %w", address, err)
 	}
 
-	s.logger.Infof("Debug endpoint listen on %s", address)
+	s.logger.Info("Debug endpoint listen on address", slog.String("address", address))
 
 	go func() {
 		if err := http.Serve(listener, s.Router); err != nil {
-			s.logger.Errorf("Error starting Debug socket server: %s", err)
+			s.logger.Error("Error starting Debug socket server", log.Err(err))
 			os.Exit(1)
 		}
 	}()
 
 	if s.HttpAddr != "" {
 		go func() {
 			if err := http.ListenAndServe(s.HttpAddr, s.Router); err != nil {
-				s.logger.Errorf("Error starting Debug HTTP server: %s", err)
+				s.logger.Error("Error starting Debug HTTP server", log.Err(err))
 				os.Exit(1)
 			}
 		}()
@@ -130,7 +131,7 @@ func handleFormattedOutput(writer http.ResponseWriter, request *http.Request, ha
 	}
 
 	format := FormatFromRequest(request)
-	structuredLogger.GetLogEntry(request).Debugf("use format '%s'", format)
+	structuredLogger.GetLogEntry(request).Debug("used format", slog.String("format", format))
 
 	switch format {
 	case "text":

pkg/executor/executor.go

@@ -21,7 +21,7 @@ import (
 func Run(cmd *exec.Cmd) error {
 	// TODO context: hook name, hook phase, hook binding
 	// TODO observability
-	log.Debugf("Executing command '%s' in '%s' dir", strings.Join(cmd.Args, " "), cmd.Dir)
+	log.Debug("Executing command", slog.String("command", strings.Join(cmd.Args, " ")), slog.String("dir", cmd.Dir))
 
 	return cmd.Run()
 }
@@ -82,7 +82,9 @@ func NewExecutor(dir string, entrypoint string, args []string, envs []string) *E
 }
 
 func (e *Executor) Output() ([]byte, error) {
-	e.logger.Debugf("Executing command '%s' in '%s' dir", strings.Join(e.cmd.Args, " "), e.cmd.Dir)
+	e.logger.Debug("Executing command",
+		slog.String("command", strings.Join(e.cmd.Args, " ")),
+		slog.String("dir", e.cmd.Dir))
 	return e.cmd.Output()
 }
 
@@ -98,7 +100,9 @@ func (e *Executor) RunAndLogLines(logLabels map[string]string) (*CmdUsage, error
 	stdoutLogEntry := logEntry.With("output", "stdout")
 	stderrLogEntry := logEntry.With("output", "stderr")
 
-	logEntry.Debugf("Executing command '%s' in '%s' dir", strings.Join(e.cmd.Args, " "), e.cmd.Dir)
+	log.Debug("Executing command",
+		slog.String("command", strings.Join(e.cmd.Args, " ")),
+		slog.String("dir", e.cmd.Dir))
 
 	plo := &proxyLogger{e.logProxyHookJSON, e.proxyJsonKey, stdoutLogEntry, make([]byte, 0)}
 	ple := &proxyLogger{e.logProxyHookJSON, e.proxyJsonKey, stderrLogEntry, make([]byte, 0)}

pkg/executor/executor_test.go

@@ -107,9 +107,8 @@ func TestRunAndLogLines(t *testing.T) {
 		_, err := ex.RunAndLogLines(map[string]string{"a": "b"})
 		assert.NoError(t, err)
 
-		assert.Equal(t, buf.String(), `{"level":"debug","msg":"Executing command 'echo [\"a\",\"b\",\"c\"]' in '' dir","source":"executor/executor.go:101","a":"b","time":"2006-01-02T15:04:05Z"}`+"\n"+
-			`{"level":"debug","msg":"json log line not map[string]interface{}","source":"executor/executor.go:173","a":"b","line":["a","b","c"],"output":"stdout","time":"2006-01-02T15:04:05Z"}`+"\n"+
-			`{"level":"info","msg":"[\"a\",\"b\",\"c\"]\n","source":"executor/executor.go:176","a":"b","output":"stdout","time":"2006-01-02T15:04:05Z"}`+"\n")
+		assert.Equal(t, buf.String(), `{"level":"debug","msg":"json log line not map[string]interface{}","source":"executor/executor.go:177","a":"b","line":["a","b","c"],"output":"stdout","time":"2006-01-02T15:04:05Z"}`+"\n"+
+			`{"level":"info","msg":"[\"a\",\"b\",\"c\"]\n","source":"executor/executor.go:180","a":"b","output":"stdout","time":"2006-01-02T15:04:05Z"}`+"\n")
 
 		buf.Reset()
 	})

pkg/hook/binding_context/binding_context.go

@@ -50,7 +50,7 @@ func (bc BindingContext) Map() map[string]interface{} {
 	case "v1":
 		return bc.MapV1()
 	default:
-		log.Errorf("Possible bug!!! Call Map for BindingContext without version.")
+		log.Error("Possible bug!!! Call Map for BindingContext without version.")
 		return make(map[string]interface{})
 	}
 }

pkg/hook/controller/admission_bindings_controller.go

@@ -1,6 +1,8 @@
 package controller
 
 import (
+	"log/slog"
+
 	"github.com/deckhouse/deckhouse/pkg/log"
 	v1 "k8s.io/api/admission/v1"
 
@@ -67,7 +69,9 @@ func (c *AdmissionBindingsController) EnableValidatingBindings() {
 			continue
 		}
 		if config.Webhook.Metadata.ConfigurationId != confId {
-			log.Errorf("Possible bug!!! kubernetesValidating has non-unique configurationIds: '%s' '%s'", config.Webhook.Metadata.ConfigurationId, confId)
+			log.Error("Possible bug!!! kubernetesValidating has non-unique configurationIds",
+				slog.String("configurationID", config.Webhook.Metadata.ConfigurationId),
+				slog.String("confID", confId))
 		}
 	}
 	c.ConfigurationId = confId
@@ -101,7 +105,9 @@ func (c *AdmissionBindingsController) EnableMutatingBindings() {
 			continue
 		}
 		if config.Webhook.Metadata.ConfigurationId != confId {
-			log.Errorf("Possible bug!!! kubernetesMutating has non-unique configurationIds: '%s' '%s'", config.Webhook.Metadata.ConfigurationId, confId)
+			log.Error("Possible bug!!! kubernetesMutating has non-unique configurationIds",
+				slog.String("configurationID", config.Webhook.Metadata.ConfigurationId),
+				slog.String("confID", confId))
 		}
 	}
 	c.ConfigurationId = confId
@@ -137,7 +143,9 @@ func (c *AdmissionBindingsController) CanHandleEvent(event admission.Event) bool
 
 func (c *AdmissionBindingsController) HandleEvent(event admission.Event) BindingExecutionInfo {
 	if c.ConfigurationId != event.ConfigurationId {
-		log.Errorf("Possible bug!!! Unknown validating event: no binding for configurationId '%s' (webhookId '%s')", event.ConfigurationId, event.WebhookId)
+		log.Error("Possible bug!!! Unknown validating event: no binding for configurationId",
+			slog.String("configurationId", event.ConfigurationId),
+			slog.String("webhookId", event.WebhookId))
 		return BindingExecutionInfo{
 			BindingContext: []bctx.BindingContext{},
 			AllowFailure:   false,
@@ -146,7 +154,9 @@ func (c *AdmissionBindingsController) HandleEvent(event admission.Event) Binding
 
 	link, hasKey := c.AdmissionLinks[event.WebhookId]
 	if !hasKey {
-		log.Errorf("Possible bug!!! Unknown validating event: no binding for configurationId '%s', webhookId '%s'", event.ConfigurationId, event.WebhookId)
+		log.Error("Possible bug!!! Unknown validating event: no binding for configurationId",
+			slog.String("configurationId", event.ConfigurationId),
+			slog.String("webhookId", event.WebhookId))
 		return BindingExecutionInfo{
 			BindingContext: []bctx.BindingContext{},
 			AllowFailure:   false,

pkg/hook/controller/conversion_bindings_controller.go

@@ -1,6 +1,8 @@
 package controller
 
 import (
+	"log/slog"
+
 	"github.com/deckhouse/deckhouse/pkg/log"
 	v1 "k8s.io/apiextensions-apiserver/pkg/apis/apiextensions/v1"
 
@@ -9,7 +11,7 @@ import (
 	"github.com/flant/shell-operator/pkg/webhook/conversion"
 )
 
-// A link between a hook and a kube monitor
+// ConversionBindingToWebhookLink a link between a hook and a kube monitor
 type ConversionBindingToWebhookLink struct {
 	BindingName string
 	// Useful fields to create a BindingContext
@@ -60,7 +62,8 @@ func (c *ConversionBindingsController) EnableConversionBindings() {
 				ToVersion:        conv.ToVersion,
 			}
 		}
-		log.Infof("conversion binding controller: add webhook from config: %v", config)
+		log.Info("conversion binding controller: add webhook from config",
+			slog.String("name", config.Webhook.Metadata.Name))
 		c.webhookManager.AddWebhook(config.Webhook)
 	}
 }
@@ -81,15 +84,17 @@ func (c *ConversionBindingsController) CanHandleEvent(crdName string, _ *v1.Conv
 func (c *ConversionBindingsController) HandleEvent(crdName string, request *v1.ConversionRequest, rule conversion.Rule) BindingExecutionInfo {
 	_, hasKey := c.Links[crdName]
 	if !hasKey {
-		log.Errorf("Possible bug!!! No binding for conversion event for crd/%s", crdName)
+		log.Error("Possible bug!!! No binding for conversion event for crd", slog.String("crd", crdName))
 		return BindingExecutionInfo{
 			BindingContext: []bctx.BindingContext{},
 			AllowFailure:   false,
 		}
 	}
 	link, has := c.Links[crdName][rule]
 	if !has {
-		log.Errorf("Possible bug!!! Event has an unknown conversion rule %s for crd/%s: no binding was registered", rule.String(), crdName)
+		log.Error("Possible bug!!! Event has an unknown conversion rule: no binding was registered",
+			slog.String("rule", rule.String()),
+			slog.String("crd", crdName))
 		return BindingExecutionInfo{
 			BindingContext: []bctx.BindingContext{},
 			AllowFailure:   false,

pkg/hook/controller/kubernetes_bindings_controller.go

@@ -2,6 +2,7 @@ package controller
 
 import (
 	"fmt"
+	"log/slog"
 
 	"github.com/deckhouse/deckhouse/pkg/log"
 
@@ -127,8 +128,10 @@ func (c *kubernetesBindingsController) UpdateMonitor(monitorId string, kind, api
 	}
 
 	utils.EnrichLoggerWithLabels(c.logger, link.BindingConfig.Monitor.Metadata.LogLabels).
-		Infof("Monitor for '%s' is recreated with new kind=%s and apiVersion=%s",
-			link.BindingConfig.BindingName, link.BindingConfig.Monitor.Kind, link.BindingConfig.Monitor.ApiVersion)
+		Info("Monitor is recreated",
+			slog.String("bindingName", link.BindingConfig.BindingName),
+			slog.String("kind", link.BindingConfig.Monitor.Kind),
+			slog.String("apiVersion", link.BindingConfig.Monitor.ApiVersion))
 
 	// Synchronization has no meaning for UpdateMonitor. Just emit Added event to handle objects of
 	// a new kind.
@@ -159,7 +162,7 @@ func (c *kubernetesBindingsController) UnlockEvents() {
 func (c *kubernetesBindingsController) UnlockEventsFor(monitorID string) {
 	m := c.kubeEventsManager.GetMonitor(monitorID)
 	if m == nil {
-		log.Warnf("monitor %q was not found", monitorID)
+		log.Warn("monitor was not found", slog.String("monitorID", monitorID))
 		return
 	}
 	m.EnableKubeEventCb()
@@ -187,7 +190,7 @@ func (c *kubernetesBindingsController) CanHandleEvent(kubeEvent kemtypes.KubeEve
 func (c *kubernetesBindingsController) HandleEvent(kubeEvent kemtypes.KubeEvent) BindingExecutionInfo {
 	link, hasKey := c.BindingMonitorLinks[kubeEvent.MonitorId]
 	if !hasKey {
-		log.Errorf("Possible bug!!! Unknown kube event: no such monitor id '%s' registered", kubeEvent.MonitorId)
+		log.Error("Possible bug!!! Unknown kube event: no such monitor id registered", slog.String("monitorID", kubeEvent.MonitorId))
 		return BindingExecutionInfo{
 			BindingContext: []bctx.BindingContext{},
 			AllowFailure:   false,

pkg/hook/hook_manager.go

@@ -1,7 +1,9 @@
 package hook
 
 import (
+	"errors"
 	"fmt"
+	"log/slog"
 	"os"
 	"os/exec"
 	"path/filepath"
@@ -92,7 +94,9 @@ func (hm *Manager) Init() error {
 	hm.hooksByName = make(map[string]*Hook)
 
 	if err := utils_file.RecursiveCheckLibDirectory(hm.workingDir); err != nil {
-		log.Errorf("failed to check lib directory %s: %v", hm.workingDir, err)
+		log.Error("failed to check lib directory",
+			slog.String("workingDir", hm.workingDir),
+			log.Err(err))
 	}
 
 	hooksRelativePaths, err := utils_file.RecursiveGetExecutablePaths(hm.workingDir)
@@ -102,7 +106,7 @@ func (hm *Manager) Init() error {
 
 	// sort hooks by path
 	sort.Strings(hooksRelativePaths)
-	log.Debugf("  Search hooks in this paths: %+v", hooksRelativePaths)
+	log.Debug("Search hooks in paths", slog.Any("paths", hooksRelativePaths))
 
 	for _, hookPath := range hooksRelativePaths {
 		hook, err := hm.loadHook(hookPath)
@@ -137,14 +141,16 @@ func (hm *Manager) loadHook(hookPath string) (*Hook, error) {
 	hook := NewHook(hookName, hookPath, app.DebugKeepTmpFiles, app.LogProxyHookJSON, app.ProxyJsonLogKey, hm.logger.Named("hook"))
 	hookEntry := hm.logger.With("hook", hook.Name).
 		With("phase", "config")
-	hookEntry.Infof("Load config from '%s'", hookPath)
+
+	hookEntry.Info("Load config", slog.String("path", hookPath))
 
 	envs := make([]string, 0)
 	configOutput, err := hm.execCommandOutput(hook.Name, hm.workingDir, hookPath, envs, []string{"--config"})
 	if err != nil {
-		hookEntry.Errorf("Hook config output:\n%s", string(configOutput))
-		if ee, ok := err.(*exec.ExitError); ok && len(ee.Stderr) > 0 {
-			hookEntry.Errorf("Hook config stderr:\n%s", string(ee.Stderr))
+		hookEntry.Error("Hook config output", slog.String("value", string(configOutput)))
+		var ee *exec.ExitError
+		if errors.As(err, &ee) && len(ee.Stderr) > 0 {
+			hookEntry.Error("Hook config stderr", slog.String("value", string(ee.Stderr)))
 		}
 		return nil, fmt.Errorf("cannot get config for hook '%s': %w", hookPath, err)
 	}
@@ -204,7 +210,7 @@ func (hm *Manager) loadHook(hookPath string) (*Hook, error) {
 		return nil, fmt.Errorf("hook %q is marked as executable but doesn't contain config section", hook.Path)
 	}
 
-	hookEntry.Infof("Loaded config: %s", hook.GetConfigDescription())
+	hookEntry.Info("Loaded config", slog.String("value", hook.GetConfigDescription()))
 
 	return hook, nil
 }
@@ -225,14 +231,14 @@ func (hm *Manager) execCommandOutput(hookName string, dir string, entrypoint str
 	debugEntry := hm.logger.With("hook", hookName).
 		With("cmd", strings.Join(args, " "))
 
-	debugEntry.Debugf("Executing hook in %s", dir)
+	debugEntry.Debug("Executing hook", slog.String("dir", dir))
 
 	output, err := hookCmd.Output()
 	if err != nil {
 		return output, err
 	}
 
-	debugEntry.Debugf("output:\n%s", string(output))
+	debugEntry.Debug("execCommandOutput", slog.String("output", string(output)))
 
 	return output, nil
 }
@@ -242,7 +248,7 @@ func (hm *Manager) GetHook(name string) *Hook {
 	if exists {
 		return hook
 	}
-	log.Errorf("Possible bug!!! Hook '%s' not found in hook manager", name)
+	log.Error("Possible bug!!! Hook not found in hook manager", slog.String("name", name))
 	return nil
 }
 
@@ -351,7 +357,12 @@ func (hm *Manager) DetectAdmissionEventType(event admission.Event) htypes.Bindin
 		}
 	}
 
-	log.Errorf("Possible bug!!! No linked hook for admission event %s %s kind=%s name=%s ns=%s", event.ConfigurationId, event.WebhookId, event.Request.Kind, event.Request.Name, event.Request.Namespace)
+	log.Error("Possible bug!!! No linked hook for admission event %s %s kind=%s name=%s ns=%s",
+		slog.String("configId", event.ConfigurationId),
+		slog.String("webhookId", event.WebhookId),
+		slog.String("kind", event.Request.Kind.String()),
+		slog.String("name", event.Request.Name),
+		slog.String("namespace", event.Request.Namespace))
 	return ""
 }
 

pkg/hook/task_metadata/task_metadata.go

@@ -2,6 +2,7 @@ package task_metadata
 
 import (
 	"fmt"
+	"log/slog"
 
 	"github.com/deckhouse/deckhouse/pkg/log"
 
@@ -51,13 +52,14 @@ var (
 func HookMetadataAccessor(t task.Task) HookMetadata {
 	meta := t.GetMetadata()
 	if meta == nil {
-		log.Errorf("Possible Bug! task metadata is nil")
+		log.Error("Possible Bug! task metadata is nil")
 		return HookMetadata{}
 	}
 
 	hookMeta, ok := meta.(HookMetadata)
 	if !ok {
-		log.Errorf("Possible Bug! task metadata is not of type HookMetadata: got %T", meta)
+		log.Error("Possible Bug! task metadata is not of type HookMetadata",
+			slog.String("type", fmt.Sprintf("%T", meta)))
 		return HookMetadata{}
 	}