Merge pull request #164 from sebastianrakel/better-logging

Switch to slog to improve logging

Author: sebastianrakel

CONFIGURATION.md

@@ -31,6 +31,9 @@ but you can pass the -config parameter to define the location of the config file
 | puppetca.readonly                      | PUPPETCA_READONLY                      | true      | bool   | Whether to allow signing / revoking / cleaning certs                                         |
 | puppetca.deactivate_nodes              | PUPPETCA_DEACTIVATE_NODES              | false     | bool   | Also deactivate node in PuppetDB with revoke / clean                                         |
 | ui_default_refresh_interval_in_seconds | UI_DEFAULT_REFRESH_INTERVAL_IN_SECONDS | 300       | int    | Default Refresh Interval in the UI (shouldn't be to small, to prevent DDoSing the openvoxdb) |
+| log_level                              | LOG_LEVEL                              | info      | string | Log Level (info,debug,warn,error)                                                            |
+| log_format                             | LOG_FORMAT                             | text      | string | Log Format (text,json)                                                                       |
+
 
 
 

config/config.go

@@ -3,13 +3,26 @@ package config
 import (
 	"flag"
 	"fmt"
-	"log"
+	"log/slog"
+	"os"
 	"sync"
 
 	"github.com/sebastianrakel/openvoxview/model"
 	"github.com/spf13/viper"
 )
 
+type LogLevel string
+type LogFormat string
+
+const (
+	LOG_LEVEL_INFO  LogLevel  = "info"
+	LOG_LEVEL_WARN  LogLevel  = "warn"
+	LOG_LEVEL_ERROR LogLevel  = "error"
+	LOG_LEVEL_DEBUG LogLevel  = "debug"
+	LOG_FORMAT_JSON LogFormat = "json"
+	LOG_FOMRAT_TEXT LogFormat = "text"
+)
+
 var configPath = flag.String("config", "", "path to the config file")
 var printVersion = flag.Bool("version", false, "prints version")
 
@@ -51,6 +64,8 @@ type Config struct {
 		ReadOnly        bool   `mapstructure:"readonly"`
 		DeactivateNodes bool   `mapstructure:"deactivate_nodes"`
 	} `mapstructure:"puppetca"`
+	LogLevel  LogLevel  `mapstructure:"log_level"`
+	LogFormat LogFormat `mapstructure:"log_format"`
 }
 
 func PrintVersion(version string) bool {
@@ -74,7 +89,7 @@ func GetConfig() (*Config, error) {
 		viper.AddConfigPath(".")
 
 		if *configPath != "" {
-			log.Printf("Using config: %s", *configPath)
+			slog.Info("Using config", "path", *configPath)
 			viper.SetConfigFile(*configPath)
 		}
 
@@ -90,6 +105,8 @@ func GetConfig() (*Config, error) {
 		viper.SetDefault("puppetca.readonly", true)
 		viper.SetDefault("puppetca.deactivate_nodes", false)
 		viper.SetDefault("ui_default_refresh_interval_in_seconds", 300)
+		viper.SetDefault("log_level", "info")
+		viper.SetDefault("log_format", "text")
 
 		viper.AutomaticEnv()
 
@@ -115,6 +132,8 @@ func GetConfig() (*Config, error) {
 		viper.BindEnv("puppetca.readonly", "PUPPETCA_READONLY")
 		viper.BindEnv("puppetca.deactivate_nodes", "PUPPETCA_DEACTIVATE_NODES")
 		viper.BindEnv("ui_default_refresh_interval_in_seconds", "UI_DEFAULT_REFRESH_INTERVAL_IN_SECONDS")
+		viper.BindEnv("log_level", "LOG_LEVEL")
+		viper.BindEnv("log_level", "LOG_FORMAT")
 
 		viper.ReadInConfig()
 
@@ -144,3 +163,31 @@ func (c *Config) GetPuppetCAAddress() string {
 
 	return fmt.Sprintf("%s://%s:%d", scheme, c.PuppetCA.Host, c.PuppetCA.Port)
 }
+
+func (c *Config) GetLogLevel() slog.Level {
+	switch c.LogLevel {
+	case LOG_LEVEL_DEBUG:
+		return slog.LevelDebug
+	case LOG_LEVEL_WARN:
+		return slog.LevelWarn
+	case LOG_LEVEL_ERROR:
+		return slog.LevelError
+	default:
+		return slog.LevelInfo
+	}
+}
+
+func (c *Config) GetLogger() *slog.Logger {
+	level := c.GetLogLevel()
+	switch c.LogFormat {
+	case LOG_FORMAT_JSON:
+		return slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{
+			Level: level,
+		}))
+	default:
+		return slog.New(slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{
+			Level: level,
+		}))
+	}
+
+}

handler/ca.go

@@ -1,7 +1,7 @@
 package handler
 
 import (
-	"log"
+	"log/slog"
 	"net/http"
 	"slices"
 	"strings"
@@ -88,12 +88,12 @@ func (h *CaHandler) QueryCertificateStatuses(c *gin.Context) {
 func (h *CaHandler) SignCertificate(c *gin.Context) {
 	name := c.Param("name")
 
-	log.Printf("[AUDIT] CA Signing: %s", name)
+	slog.Info("ca signing", "certname", name)
 
 	err := h.caClient.SignCertificate(name)
 
 	if err != nil {
-		log.Printf("Error signing certificate: %s", err)
+		slog.Error("error signing certificate", "error", err)
 		c.AbortWithStatusJSON(http.StatusInternalServerError, NewErrorResponse(err))
 		return
 	}
@@ -104,12 +104,12 @@ func (h *CaHandler) SignCertificate(c *gin.Context) {
 func (h *CaHandler) RevokeCertificate(c *gin.Context) {
 	name := c.Param("name")
 
-	log.Printf("[AUDIT] CA Revoking: %s", name)
+	slog.Info("ca revoking", "certname", name)
 
 	err := h.caClient.RevokeCertificate(name)
 
 	if err != nil {
-		log.Printf("Error revoking certificate: %s", err)
+		slog.Error("error revoking certificate", "error", err)
 		c.AbortWithStatusJSON(http.StatusInternalServerError, NewErrorResponse(err))
 		return
 	}
@@ -126,12 +126,12 @@ func (h *CaHandler) RevokeCertificate(c *gin.Context) {
 func (h *CaHandler) CleanCertificate(c *gin.Context) {
 	name := c.Param("name")
 
-	log.Printf("[AUDIT] CA Cleaning: %s", name)
+	slog.Info("ca cleaning", "certname", name)
 
 	err := h.caClient.CleanCertificate(name)
 
 	if err != nil {
-		log.Printf("Error cleaning certificate: %s", err)
+		slog.Error("error cleaning certificate", "error", err)
 		c.AbortWithStatusJSON(http.StatusInternalServerError, NewErrorResponse(err))
 		return
 	}
@@ -150,15 +150,15 @@ func (h *CaHandler) deactivateNode(certname string) error {
 		return nil
 	}
 
-	log.Printf("[AUDIT] Deactivating node: %s", certname)
+	slog.Info("ca deactivating node", "certname", certname)
 
 	pdb := puppetdb.NewClient()
 	resp, err := pdb.DeactivateNode(certname)
 
 	if err != nil {
-		log.Printf("Error deactivating node: %s", err)
+		slog.Error("error deactivating certificate", "error", err)
 	} else {
-		log.Printf("Deactivated node %s with command UUID: %s", certname, resp.Uuid)
+		slog.Info("deactivated node", "certname", certname, "uuid", resp.Uuid)
 	}
 
 	return err

handler/pdb.go

@@ -2,7 +2,7 @@ package handler
 
 import (
 	"encoding/json"
-	"log"
+	"log/slog"
 	"net/http"
 	"time"
 
@@ -47,7 +47,7 @@ func (h *PdbHandler) PdbExecuteQuery(c *gin.Context) {
 	c.BindJSON(&queryRequest)
 
 	dbClient := puppetdb.NewClient()
-	log.Printf("Executing Query: %s", queryRequest.Query)
+	slog.Debug("executing query", "query", queryRequest.Query)
 
 	historyEntry := PqlHistoryEntry{
 		Query: queryRequest,

main.go

@@ -3,9 +3,10 @@ package main
 import (
 	"fmt"
 	"io/fs"
-	"log"
+	"log/slog"
 	"net/http"
 	"strings"
+	"time"
 
 	"github.com/gin-gonic/gin"
 	"github.com/sebastianrakel/openvoxview/config"
@@ -21,18 +22,22 @@ func main() {
 	if config.PrintVersion(VERSION) {
 		return
 	}
-	log.Printf("OpenVox View - %s (%s)", VERSION, COMMIT)
 	cfg, err := config.GetConfig()
 	if err != nil {
 		panic(err)
 	}
 
-	log.Printf("LISTEN: %s", cfg.Listen)
-	log.Printf("PORT: %d", cfg.Port)
-	log.Printf("PUPPETDB_ADDRESS: %s", cfg.GetPuppetDbAddress())
-	log.Printf("TRUSTED_PROXIES: %#v", cfg.TrustedProxies)
+	logger := cfg.GetLogger()
+	slog.SetDefault(logger)
 
-	r := gin.Default()
+	slog.Info(fmt.Sprintf("OpenVox View - %s (%s)", VERSION, COMMIT))
+	slog.Info(fmt.Sprintf("LISTEN: %s", cfg.Listen))
+	slog.Info(fmt.Sprintf("PORT: %d", cfg.Port))
+	slog.Info(fmt.Sprintf("PUPPETDB_ADDRESS: %s", cfg.GetPuppetDbAddress()))
+	slog.Info(fmt.Sprintf("TRUSTED_PROXIES: %s", cfg.TrustedProxies))
+
+	r := gin.New()
+	r.Use(SlogMiddleware(logger))
 
 	r.NoRoute(func(c *gin.Context) {
 		if strings.HasPrefix(c.Request.URL.Path, "/api/") {
@@ -45,7 +50,6 @@ func main() {
 
 	uiFSSub, _ := fs.Sub(uiFS, "ui/dist/spa")
 	r.StaticFS("ui", http.FS(uiFSSub))
-
 	r.Use(AllowCORS)
 
 	if len(cfg.TrustedProxies) > 0 {
@@ -135,3 +139,29 @@ func AllowCORS(c *gin.Context) {
 
 	c.Next()
 }
+
+func SlogMiddleware(logger *slog.Logger) gin.HandlerFunc {
+	return func(c *gin.Context) {
+		start := time.Now()
+		path := c.Request.URL.Path
+		query := c.Request.URL.RawQuery
+
+		c.Next()
+
+		logger.Info("request",
+			slog.String("method", c.Request.Method),
+			slog.String("path", path),
+			slog.String("query", query),
+			slog.Int("status", c.Writer.Status()),
+			slog.Duration("latency", time.Since(start)),
+			slog.String("client_ip", c.ClientIP()),
+			slog.Int("body_size", c.Writer.Size()),
+		)
+
+		if len(c.Errors) > 0 {
+			for _, err := range c.Errors {
+				logger.Error("request error", slog.String("error", err.Error()))
+			}
+		}
+	}
+}

puppetca/client.go

@@ -7,6 +7,7 @@ import (
 	"encoding/json"
 	"fmt"
 	"io"
+	"log/slog"
 	"net/http"
 	"net/url"
 	"os"
@@ -39,12 +40,11 @@ func (c *Client) call(httpMethod string, endpoint string, payload any, query url
 	if payload != nil {
 		data, err = json.Marshal(&payload)
 		if err != nil {
-			fmt.Printf("err: %s", err)
+			slog.Error("error marshal payload", "error", err)
 		}
-		fmt.Printf("Payload:\n%s\n", data)
 	}
 
-	fmt.Printf("HTTP: %#v: %#v\n", httpMethod, uri)
+	slog.Debug("puppet ca call", "method", httpMethod, "url", uri)
 
 	if c.transport == nil {
 		var tlsConfig *tls.Config

puppetdb/client.go

@@ -8,6 +8,7 @@ import (
 	"errors"
 	"fmt"
 	"io"
+	"log/slog"
 	"net/http"
 	"net/url"
 	"os"
@@ -47,12 +48,11 @@ func (c *client) call(httpMethod string, endpoint string, payload any, query url
 	if payload != nil {
 		data, err = json.Marshal(&payload)
 		if err != nil {
-			fmt.Printf("err: %s", err)
+			slog.Error("error marshal payload", "error", err)
 		}
-		fmt.Printf("Payload:\n%s\n", data)
 	}
 
-	fmt.Printf("HTTP: %#v: %#v\n", httpMethod, uri)
+	slog.Debug("puppet db call", "method", httpMethod, "url", uri)
 
 	var tlsConfig *tls.Config