Use slog logging

Drop go-kit/kit/log in favor of the now standard log/slog.

10 files changed, 57 insertions, 73 deletions

diff --git a/internal/environment/environment.go b/internal/environment/environment.go
index 8dad2c9..0bcb4a7 100644
--- a/internal/environment/environment.go
+++ b/internal/environment/environment.go
@@ -73,7 +73,7 @@ func New() *Environment {
 
 	env.EventLog = &event.Log{}
 
-	env.Logger.Info("component", "environment", "msg", "Override found", "environment", env.Environments)
+	env.Logger.Info("override found", "component", "environment", "environment", env.Environments)
 
 	mappingsPath := path.Join(env.DataDir, env.MappingsFile)
 	if err := env.initMappings(mappingsPath); err != nil {
@@ -113,7 +113,7 @@ func (env *Environment) initStaticTemplates() {
 
 	for _, t := range staticTemplates {
 		if _, err := os.Stat(t); err != nil {
-			env.Logger.Error("component", "environment", "msg", "Template does not exists!", "environment", t)
+			env.Logger.Error("template does not exist", "component", "environment", "template", t)
 			os.Exit(1)
 		}
 	}
diff --git a/internal/handlers/events.go b/internal/handlers/events.go
index f794343..9480169 100644
--- a/internal/handlers/events.go
+++ b/internal/handlers/events.go
@@ -26,7 +26,7 @@ func ListEvents(w http.ResponseWriter, r *http.Request) {
 	env := envFromRequest(r)
 	eventList, err := json.Marshal(env.EventLog.Events)
 	if err != nil {
-		env.Logger.Error("component", "handler", "err", err)
+		env.Logger.Error("marshal events failed", "component", "handler", "err", err)
 		os.Exit(1)
 	}
 
diff --git a/internal/handlers/middleware.go b/internal/handlers/middleware.go
index 9525efb..7ad00a0 100644
--- a/internal/handlers/middleware.go
+++ b/internal/handlers/middleware.go
@@ -55,7 +55,7 @@ func loggingMiddleware(h http.Handler) http.Handler {
 	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
 		logger := envFromRequest(r).Logger
 
-		logger.Info("component", "http", "type", "request", "src", r.RemoteAddr, "method", r.Method, "url", r.URL)
+		logger.Info("http request", "component", "http", "type", "request", "src", r.RemoteAddr, "method", r.Method, "url", r.URL)
 		h.ServeHTTP(w, r)
 	})
 }
diff --git a/internal/handlers/polling.go b/internal/handlers/polling.go
index 51fd8ad..c5aeb50 100644
--- a/internal/handlers/polling.go
+++ b/internal/handlers/polling.go
@@ -32,12 +32,11 @@ import (
 func StartPollingHandler(w http.ResponseWriter, r *http.Request) {
 	env := envFromRequest(r)
 
-	script := polling.GenStartScript(env.Logger,  env.BaseURL)
+	script := polling.GenStartScript(env.Logger, env.BaseURL)
 
 	w.Write([]byte(script))
 }
 
-
 // PollHandler is called by iPXE boot agents. It returns the boot script
 // specified on the configuration or, if the host is unknown, it makes it
 // retry for a while until the user specifies alternative IPXE boot script.
@@ -84,7 +83,7 @@ func ServerListHandler(w http.ResponseWriter, r *http.Request) {
 
 	servers, err := json.Marshal(polling.ListServers(env.ServerStates))
 	if err != nil {
-		env.Logger.Error("component", "handler", "err", err)
+		env.Logger.Error("marshal servers failed", "component", "handler", "err", err)
 		os.Exit(1)
 	}
 
@@ -147,16 +146,16 @@ func parsePostForm(form map[string][]string) (mac, scriptName, environment strin
 
 func validateMACAndIP(logger log.Logger, mac string, ip string) (err error) {
 	if !utils.IsValidMAC(mac) {
-		logger.Error("component", "polling", "msg", "Invalid MAC", "mac", mac)
+		logger.Error("invalid mac", "component", "polling", "mac", mac)
 		return fmt.Errorf("%s", "Invalid MAC")
 	}
 
 	if !utils.IsValidIP(ip) {
-		logger.Error("component", "polling", "msg", "Invalid IP", "ip", ip)
+		logger.Error("invalid ip", "component", "polling", "ip", ip)
 		return fmt.Errorf("%s", "Invalid IP")
 	}
 
-	logger.Debug("component", "polling", "msg", "MAC and IP validated", "mac", mac, "ip", ip)
+	logger.Debug("mac and ip validated", "component", "polling", "mac", mac, "ip", ip)
 
 	return nil
 }
@@ -164,7 +163,7 @@ func validateMACAndIP(logger log.Logger, mac string, ip string) (err error) {
 func resolveHostname(logger log.Logger, ip string) string {
 	host := utils.ResolveHostname(ip)
 	if host == "" {
-		logger.Info("component", "polling", "msg", "Can't resolve IP", "ip", ip)
+		logger.Info("can't resolve ip", "component", "polling", "ip", ip)
 	}
 
 	return host
diff --git a/internal/ipxe/ipxescript.go b/internal/ipxe/ipxescript.go
index 7253195..b5a8112 100644
--- a/internal/ipxe/ipxescript.go
+++ b/internal/ipxe/ipxescript.go
@@ -69,7 +69,7 @@ func appendScriptsFromDir(logger log.Logger, scripts []Script, templateExtension
 func scriptDirList(logger log.Logger, templateExtension string, datadir string) []ScriptName {
 	files, err := ioutil.ReadDir(datadir)
 	if err != nil {
-		logger.Info("component=ipxescript action=dir-list dir=%s err=\"%v\"", datadir, err.Error())
+		logger.Info("list ipxe scripts failed", "component", "ipxescript", "dir", datadir, "err", err)
 		return nil
 	}
 
diff --git a/internal/log/log.go b/internal/log/log.go
index 071a816..924abd9 100644
--- a/internal/log/log.go
+++ b/internal/log/log.go
@@ -16,46 +16,31 @@ package log
 
 import (
 	"io"
-
-	"github.com/go-kit/kit/log"
-	"github.com/go-kit/kit/log/level"
+	"log/slog"
 )
 
-// Logger struct holds a log.Logger plus functions required for logging
-// with different levels. They functions are syntactic sugar to avoid
-// having to import "github.com/go-kit/kit/log/level" in every package that
-// has to cast a log.
+// Logger wraps slog with the level switch Shoelaces uses for debug mode.
 type Logger struct {
-	Raw   log.Logger
-	Info  func(...interface{}) error
-	Debug func(...interface{}) error
-	Error func(...interface{}) error
+	*slog.Logger
+	level *slog.LevelVar
 }
 
-const callerLevel int = 6
-
 // MakeLogger receives a io.Writer and return a Logger struct.
 func MakeLogger(w io.Writer) Logger {
-	raw := log.NewLogfmtLogger(log.NewSyncWriter(w))
-	raw = log.With(raw, "ts", log.DefaultTimestampUTC, "caller", log.Caller(callerLevel))
-	filtered := level.NewFilter(raw, level.AllowInfo())
+	level := &slog.LevelVar{}
+	level.Set(slog.LevelInfo)
 
 	return Logger{
-		Raw:   raw,
-		Info:  level.Info(filtered).Log,
-		Debug: level.Debug(filtered).Log,
-		Error: level.Error(filtered).Log,
+		Logger: slog.New(slog.NewTextHandler(w, &slog.HandlerOptions{
+			AddSource: true,
+			Level:     level,
+		})),
+		level: level,
 	}
 }
 
 // AllowDebug receives a Logger and enables the debug logging level.
 func AllowDebug(l Logger) Logger {
-	filtered := level.NewFilter(l.Raw, level.AllowDebug())
-
-	return Logger{
-		Raw:   l.Raw,
-		Info:  level.Info(filtered).Log,
-		Debug: level.Debug(filtered).Log,
-		Error: level.Error(filtered).Log,
-	}
+	l.level.Set(slog.LevelDebug)
+	return l
 }
diff --git a/internal/mappings/parse.go b/internal/mappings/parse.go
index 64de5bb..dbd9552 100644
--- a/internal/mappings/parse.go
+++ b/internal/mappings/parse.go
@@ -57,11 +57,11 @@ type YamlScript struct {
 func ParseYamlMappings(logger log.Logger, mappingsFile string) *Mappings {
 	var mappings Mappings
 
-	logger.Info("component", "config", "msg", "Reading mappings", "source", mappingsFile)
+	logger.Info("reading mappings", "component", "config", "source", mappingsFile)
 	yamlFile, err := ioutil.ReadFile(mappingsFile)
 
 	if err != nil {
-		logger.Error(err)
+		logger.Error("read mappings failed", "err", err)
 		os.Exit(1)
 	}
 
@@ -70,7 +70,7 @@ func ParseYamlMappings(logger log.Logger, mappingsFile string) *Mappings {
 
 	err = yaml.Unmarshal(yamlFile, &mappings)
 	if err != nil {
-		logger.Error(err)
+		logger.Error("parse mappings failed", "err", err)
 		os.Exit(1)
 	}
 
diff --git a/internal/polling/polling.go b/internal/polling/polling.go
index 875d8db..49780a0 100644
--- a/internal/polling/polling.go
+++ b/internal/polling/polling.go
@@ -115,7 +115,7 @@ func UpdateTarget(logger log.Logger, serverStates *server.States,
 	}
 
 	hostname := servers[srv.Mac].Server.Hostname
-	logger.Debug("component", "polling", "msg", "Setting server override", "server", srv.Mac, "target", scriptName, "environment", envName, "hostname", hostname, "params", params)
+	logger.Debug("setting server override", "component", "polling", "server", srv.Mac, "target", scriptName, "environment", envName, "hostname", hostname, "params", params)
 	eventLog.AddEvent(event.UserSelection, srv, "", scriptName, nil)
 	servers[srv.Mac].Target = scriptName
 	servers[srv.Mac].Environment = envName
@@ -145,24 +145,24 @@ func attemptAutomaticBoot(logger log.Logger, hostnameMaps []mappings.HostnameMap
 
 	// Find with reverse hostname matched with the hostname regexps
 	if script, found := mappings.FindScriptForHostname(hostnameMaps, srv.Hostname); found {
-		logger.Debug("component", "polling", "msg", "Host found", "where", "hostname-mapping", "host", srv.Hostname)
+		logger.Debug("host found", "component", "polling", "where", "hostname-mapping", "host", srv.Hostname)
 		eventLog.AddEvent(event.HostBoot, srv, event.PtrMatchBoot, script.Name, script.Params)
 		script.Params["hostname"] = srv.Hostname
 
 		return genBootScript(logger, templateRenderer, baseURL, script), found
 	}
-	logger.Debug("component", "polling", "msg", "Host not found", "where", "hostname-mapping", "host", srv.Hostname)
+	logger.Debug("host not found", "component", "polling", "where", "hostname-mapping", "host", srv.Hostname)
 
 	// Find with IP belonging to a configured subnet
 	if script, found := mappings.FindScriptForNetwork(networkMaps, srv.IP); found {
-		logger.Debug("component", "polling", "msg", "Host found", "where", "network-mapping", "ip", srv.IP)
+		logger.Debug("host found", "component", "polling", "where", "network-mapping", "ip", srv.IP)
 		setHostName(script.Params, srv.Mac)
 		srv.Hostname = script.Params["hostname"].(string)
 		eventLog.AddEvent(event.HostBoot, srv, event.SubnetMatchBoot, script.Name, script.Params)
 
 		return genBootScript(logger, templateRenderer, baseURL, script), found
 	}
-	logger.Debug("component", "polling", "msg", "Host not found", "where", "network-mapping", "ip", srv.IP)
+	logger.Debug("host not found", "component", "polling", "where", "network-mapping", "ip", srv.IP)
 
 	return "", false
 }
@@ -171,7 +171,7 @@ func manualAction(logger log.Logger, serverStates *server.States, templateRender
 	eventLog *event.Log, baseURL string, srv server.Server) (scriptText string, err error) {
 
 	script, action := chooseManualAction(logger, serverStates, eventLog, srv)
-	logger.Debug("component", "polling", "target-script-name", script, "action", action)
+	logger.Debug("manual action selected", "component", "polling", "target-script-name", script, "action", action)
 
 	switch action {
 	case BootAction:
@@ -187,7 +187,7 @@ func manualAction(logger log.Logger, serverStates *server.States, templateRender
 		return timeoutScript, nil
 
 	default:
-		logger.Info("component", "polling", "msg", "Unknown action")
+		logger.Info("unknown action", "component", "polling")
 		return "", fmt.Errorf("%s", "Unknown action")
 	}
 }
@@ -201,7 +201,7 @@ func chooseManualAction(logger log.Logger, serverStates *server.States,
 	if m := serverStates.Servers[srv.Mac]; m != nil {
 		if m.Target != server.InitTarget {
 			serverStates.DeleteServer(srv.Mac)
-			logger.Debug("component", "polling", "msg", "Server boot", "mac", srv.Mac)
+			logger.Debug("server boot", "component", "polling", "mac", srv.Mac)
 			return &mappings.Script{
 				Name:        m.Target,
 				Environment: m.Environment,
@@ -209,17 +209,17 @@ func chooseManualAction(logger log.Logger, serverStates *server.States,
 		} else if m.Retry <= maxRetry {
 			m.Retry++
 			m.LastAccess = int(time.Now().UTC().Unix())
-			logger.Debug("component", "polling", "msg", "Retrying reboot", "mac", srv.Mac)
+			logger.Debug("retrying reboot", "component", "polling", "mac", srv.Mac)
 			return nil, RetryAction
 		} else {
 			serverStates.DeleteServer(srv.Mac)
-			logger.Debug("component", "polling", "msg", "Timing out server", "mac", srv.Mac)
+			logger.Debug("timing out server", "component", "polling", "mac", srv.Mac)
 			return nil, TimeoutAction
 		}
 	}
 
 	serverStates.AddServer(srv)
-	logger.Debug("component", "polling", "msg", "New server", "mac", srv.Mac)
+	logger.Debug("new server", "component", "polling", "mac", srv.Mac)
 	eventLog.AddEvent(event.HostPoll, srv, "", "", nil)
 
 	return nil, RetryAction
@@ -246,14 +246,14 @@ func GenStartScript(logger log.Logger, baseURL string) string {
 
 	tmpl, err := template.New("retry").Parse(startScript)
 	if err != nil {
-		logger.Info("component", "polling", "msg", "Error parsing start template")
+		logger.Info("error parsing start template", "component", "polling")
 		panic(err)
 	}
 
 	variablesMap["baseURL"] = baseURL
 	err = tmpl.Execute(parsedTemplate, variablesMap)
 	if err != nil {
-		logger.Info("component", "polling", "msg", "Error executing start template")
+		logger.Info("error executing start template", "component", "polling")
 		panic(err)
 	}
 
@@ -275,7 +275,7 @@ func genRetryScript(logger log.Logger, baseURL string, mac string) string {
 
 	tmpl, err := template.New("retry").Parse(retryScript)
 	if err != nil {
-		logger.Info("component", "polling", "msg", "Error parsing retry template", "mac", mac)
+		logger.Info("error parsing retry template", "component", "polling", "mac", mac)
 		panic(err)
 	}
 
@@ -283,7 +283,7 @@ func genRetryScript(logger log.Logger, baseURL string, mac string) string {
 	variablesMap["macAddress"] = utils.MacColonToDash(mac)
 	err = tmpl.Execute(parsedTemplate, variablesMap)
 	if err != nil {
-		logger.Info("component", "polling", "msg", "Error executing retry template", "mac", mac)
+		logger.Info("error executing retry template", "component", "polling", "mac", mac)
 		panic(err)
 	}
 
diff --git a/internal/server/server.go b/internal/server/server.go
index 1bc7e88..55f82b0 100644
--- a/internal/server/server.go
+++ b/internal/server/server.go
@@ -108,13 +108,13 @@ func StartStateCleaner(logger log.Logger, serverStates *States) {
 			servers := serverStates.Servers
 			expire := int(time.Now().UTC().Unix()) - expireAfterSec
 
-			logger.Debug("component", "polling", "msg", "Cleaning", "before", time.Unix(int64(expire), 0))
+			logger.Debug("cleaning server states", "component", "polling", "before", time.Unix(int64(expire), 0))
 
 			serverStates.Lock()
 			for mac, state := range servers {
 				if state.LastAccess <= expire {
 					delete(servers, mac)
-					logger.Debug("component", "polling", "msg", "Mac cleaned", "mac", mac)
+					logger.Debug("mac cleaned", "component", "polling", "mac", mac)
 				}
 			}
 			serverStates.Unlock()
diff --git a/internal/templates/templates.go b/internal/templates/templates.go
index 0df384a..6de4ec1 100644
--- a/internal/templates/templates.go
+++ b/internal/templates/templates.go
@@ -67,7 +67,7 @@ func New() *ShoelacesTemplates {
 func (s *ShoelacesTemplates) parseTemplateInfo(logger log.Logger, path string) shoelacesTemplateInfo {
 	fh, err := os.Open(path)
 	if err != nil {
-		logger.Error("component", "template", "err", err.Error())
+		logger.Error("open template failed", "component", "template", "err", err)
 		os.Exit(1)
 	}
 
@@ -103,7 +103,7 @@ func (s *ShoelacesTemplates) checkAddEnvironment(logger log.Logger, environment
 	if _, ok := s.envTemplates[environment]; !ok {
 		c, e := s.envTemplates[defaultEnvironment].templateObj.Clone()
 		if e != nil {
-			logger.Error("component", "template", "msg", "Template for environment already executed", "environment", environment)
+			logger.Error("template for environment already executed", "component", "template", "environment", environment)
 			os.Exit(1)
 		}
 		s.envTemplates[environment] = shoelacesTemplateEnvironment{
@@ -139,16 +139,16 @@ func (s *ShoelacesTemplates) ParseTemplates(logger log.Logger, dataDir string, e
 	s.envDir = envDir
 	s.tplExt = tplExt
 
-	logger.Debug("component", "template", "msg", "Template parsing started", "dir", dataDir)
+	logger.Debug("template parsing started", "component", "template", "dir", dataDir)
 
 	tplScannerDefault := func(p string, info os.FileInfo, err error) error {
 		if strings.HasPrefix(p, path.Join(dataDir, envDir)) {
 			return err
 		}
 		if strings.HasSuffix(p, tplExt) {
-			logger.Info("component", "template", "msg", "Parsing file", "file", p)
+			logger.Info("parsing file", "component", "template", "file", p)
 			if err := s.addTemplate(logger, p, defaultEnvironment); err != nil {
-				logger.Error("component", "template", "err", err.Error())
+				logger.Error("parse template failed", "component", "template", "err", err)
 				os.Exit(1)
 			}
 		}
@@ -158,10 +158,10 @@ func (s *ShoelacesTemplates) ParseTemplates(logger log.Logger, dataDir string, e
 	tplScannerOverride := func(p string, info os.FileInfo, err error) error {
 		if strings.HasSuffix(p, tplExt) {
 			env := s.getEnvFromPath(p)
-			logger.Info("component", "template", "msg", "Parsing ovveride", "environment", env, "file", p)
+			logger.Info("parsing override", "component", "template", "environment", env, "file", p)
 
 			if err := s.addTemplate(logger, p, env); err != nil {
-				logger.Error("component", "template", "err", err.Error())
+				logger.Error("parse template override failed", "component", "template", "err", err)
 				os.Exit(1)
 			}
 		}
@@ -171,11 +171,11 @@ func (s *ShoelacesTemplates) ParseTemplates(logger log.Logger, dataDir string, e
 	if err := filepath.Walk(dataDir, tplScannerDefault); err != nil {
 		panic(err)
 	}
-	logger.Info("component", "template", "msg", "Parsing override files", "dir", path.Join(dataDir, envDir))
+	logger.Info("parsing override files", "component", "template", "dir", path.Join(dataDir, envDir))
 	if err := filepath.Walk(path.Join(dataDir, envDir), tplScannerOverride); err != nil {
-		logger.Info("component", "template", "msg", "No overrides found")
+		logger.Info("no overrides found", "component", "template")
 	}
-	logger.Debug("component", "template", "msg", "Parsing ended")
+	logger.Debug("template parsing ended", "component", "template")
 }
 
 // RenderTemplate receives a name and a map of parameters, among other
@@ -185,7 +185,7 @@ func (s *ShoelacesTemplates) RenderTemplate(logger log.Logger, configName string
 	if envName == "" {
 		envName = defaultEnvironment
 	}
-	logger.Info("component", "template", "action", "template-request", "template", configName, "env", envName, "parameters", utils.MapToString(paramMap))
+	logger.Info("template request", "component", "template", "template", configName, "env", envName, "parameters", utils.MapToString(paramMap))
 
 	requiredVariables := s.envTemplates[envName].templateVars[configName]
 
@@ -198,7 +198,7 @@ func (s *ShoelacesTemplates) RenderTemplate(logger log.Logger, configName string
 		err = s.envTemplates[defaultEnvironment].templateObj.ExecuteTemplate(&b, configName, paramMap)
 	}
 	if err != nil {
-		logger.Info("component", "template", "action", "render-template", "err", err.Error())
+		logger.Info("render template failed", "component", "template", "err", err)
 		return "", err
 	}
 	r := b.String()
@@ -212,7 +212,7 @@ func (s *ShoelacesTemplates) RenderTemplate(logger log.Logger, configName string
 				missingVariables += requiredVariable
 			}
 		}
-		logger.Info("component", "template", "msg", "Missing variables in request", "variables", missingVariables)
+		logger.Info("missing variables in request", "component", "template", "variables", missingVariables)
 		return "", errors.New("Missing variables in request: " + missingVariables)
 	}