Verbose vault logging

Dockerfile.dev

@@ -1,4 +1,4 @@
-FROM golang:1.21-alpine as build
+FROM golang:1.22-alpine as build
 
 LABEL maintainer="MinIO Inc <[email protected]>"
 

cmd/kes/server.go

@@ -79,13 +79,15 @@ func serverCmd(args []string) {
 		tlsCertFlag  string
 		mtlsAuthFlag string
 		devFlag      bool
+		verboseFlag  bool
 	)
 	cmd.StringVar(&addrFlag, "addr", "", "The address of the server")
 	cmd.StringVar(&configFlag, "config", "", "Path to the server configuration file")
 	cmd.StringVar(&tlsKeyFlag, "key", "", "Path to the TLS private key")
 	cmd.StringVar(&tlsCertFlag, "cert", "", "Path to the TLS certificate")
 	cmd.StringVar(&mtlsAuthFlag, "auth", "", "Controls how the server handles mTLS authentication")
 	cmd.BoolVar(&devFlag, "dev", false, "Start the KES server in development mode")
+	cmd.BoolVar(&verboseFlag, "verbose", false, "Log verbose output")
 	if err := cmd.Parse(args[1:]); err != nil {
 		if errors.Is(err, flag.ErrHelp) {
 			os.Exit(2)
@@ -122,12 +124,12 @@ func serverCmd(args []string) {
 		return
 	}
 
-	if err := startServer(addrFlag, configFlag); err != nil {
+	if err := startServer(addrFlag, configFlag, verboseFlag); err != nil {
 		cli.Fatal(err)
 	}
 }
 
-func startServer(addrFlag, configFlag string) error {
+func startServer(addrFlag, configFlag string, verbose bool) error {
 	var memLocked bool
 	if runtime.GOOS == "linux" {
 		memLocked = mlockall() == nil
@@ -174,18 +176,26 @@ func startServer(addrFlag, configFlag string) error {
 	ctx, cancel := signal.NotifyContext(context.Background(), syscall.SIGINT, syscall.SIGTERM)
 	defer cancel()
 
+	srv := &kes.Server{}
+	logLevel := slog.LevelInfo
+	if rawConfig.Log != nil {
+		srv.ErrLevel.Set(rawConfig.Log.ErrLevel)
+		srv.AuditLevel.Set(rawConfig.Log.AuditLevel)
+		logLevel = rawConfig.Log.LogLevel
+	}
+	if verbose {
+		logLevel = slog.LevelDebug
+	}
+	slog.SetLogLoggerLevel(logLevel)
+
 	conf, err := rawConfig.Config(ctx)
 	if err != nil {
 		return err
 	}
 	defer conf.Keys.Close()
 
-	srv := &kes.Server{}
 	conf.Cache = configureCache(conf.Cache)
-	if rawConfig.Log != nil {
-		srv.ErrLevel.Set(rawConfig.Log.ErrLevel)
-		srv.AuditLevel.Set(rawConfig.Log.AuditLevel)
-	}
+
 	sighup := make(chan os.Signal, 10)
 	signal.Notify(sighup, syscall.SIGHUP)
 	defer signal.Stop(sighup)

go.mod

@@ -1,6 +1,6 @@
 module github.com/minio/kes
 
-go 1.21
+go 1.22
 
 toolchain go1.23.5
 

internal/keystore/vault/log.go

@@ -0,0 +1,64 @@
+package vault
+
+import (
+	"crypto/sha256"
+	"encoding/hex"
+	"fmt"
+	"log/slog"
+	"net/http"
+	"time"
+
+	vaultapi "github.com/hashicorp/vault/api"
+)
+
+type loggingTransport struct {
+	http.RoundTripper
+}
+
+func (lt *loggingTransport) RoundTrip(req *http.Request) (*http.Response, error) {
+	rt := lt.RoundTripper
+	if rt == nil {
+		rt = http.DefaultTransport
+	}
+
+	start := time.Now()
+	resp, err := rt.RoundTrip(req)
+
+	// don't log health checks
+	if req.URL.Path != "/v1/sys/health" {
+		auth := obfuscateToken(req.Header.Get(vaultapi.AuthHeaderName))
+		switch {
+		case err != nil:
+			slog.Debug("HTTP error",
+				slog.String("method", req.Method),
+				slog.String("url", req.URL.String()),
+				slog.String("auth", auth),
+				slog.Duration("duration", time.Since(start)),
+				slog.String("error", err.Error()))
+		case resp.StatusCode >= 300:
+			slog.Debug("HTTP error response",
+				slog.String("method", req.Method),
+				slog.String("url", req.URL.String()),
+				slog.String("auth", auth),
+				slog.Duration("duration", time.Since(start)),
+				slog.String("status", resp.Status))
+		default:
+			slog.Debug("HTTP success response",
+				slog.String("method", req.Method),
+				slog.String("url", req.URL.String()),
+				slog.String("auth", auth),
+				slog.Duration("duration", time.Since(start)),
+				slog.String("status", resp.Status))
+		}
+	}
+
+	return resp, err
+}
+
+func obfuscateToken(token string) string {
+	if len(token) == 0 {
+		return ""
+	}
+	hash := sha256.Sum256([]byte(token))
+	return fmt.Sprintf("%s (hashed)", hex.EncodeToString(hash[:16]))
+}

internal/keystore/vault/vault.go

@@ -17,6 +17,7 @@ import (
 	"encoding/base64"
 	"errors"
 	"fmt"
+	"log/slog"
 	"net/http"
 	"os"
 	"path"
@@ -112,6 +113,9 @@ func Connect(ctx context.Context, c *Config) (*Store, error) {
 		tr.DisableKeepAlives = true
 		tr.MaxIdleConnsPerHost = -1
 	}
+	if slog.Default().Enabled(ctx, slog.LevelDebug) {
+		config.HttpClient.Transport = &loggingTransport{config.HttpClient.Transport}
+	}
 	vaultClient, err := vaultapi.NewClient(config)
 	if err != nil {
 		return nil, err
@@ -135,7 +139,25 @@ func Connect(ctx context.Context, c *Config) (*Store, error) {
 		authenticate = client.AuthenticateWithK8S(c.K8S)
 	}
 
-	auth, err := authenticate(ctx)
+	// log authentication events
+	lastAuthSuccess := false
+	authenticateLogged := func(ctx context.Context) (*vaultapi.Secret, error) {
+		secret, err := authenticate(ctx)
+		if err != nil {
+			if lastAuthSuccess {
+				slog.Info("Authentication failed (not logged anymore until next successful authentication)", slog.String("error", err.Error()))
+				lastAuthSuccess = false
+			}
+		} else {
+			if slog.Default().Enabled(ctx, slog.LevelDebug) {
+				slog.Debug("Authentication successful", slog.String("token", obfuscateToken(secret.Auth.ClientToken)))
+			}
+			lastAuthSuccess = true
+		}
+		return secret, err
+	}
+
+	auth, err := authenticateLogged(ctx)
 	if err != nil {
 		return nil, err
 	}

internal/sys/build.go

@@ -16,7 +16,7 @@ import (
 type BinaryInfo struct {
 	Version  string // The version of this binary
 	CommitID string // The git commit hash
-	Runtime  string // The Go runtime version, e.g. go1.21.0
+	Runtime  string // The Go runtime version, e.g. go1.22.0
 	Compiler string // The Go compiler used to build this binary
 }
 

kesconf/config.go

@@ -66,6 +66,7 @@ type ymlFile struct {
 	Log struct {
 		Error env[string] `yaml:"error"`
 		Audit env[string] `yaml:"audit"`
+		Level env[string] `yaml:"level"`
 	} `yaml:"log"`
 
 	Keys []struct {
@@ -299,6 +300,10 @@ func ymlToServerConfig(y *ymlFile) (*File, error) {
 	if err != nil {
 		return nil, err
 	}
+	logLevel, err := parseLogLevel(y.Log.Level.Value)
+	if err != nil {
+		return nil, err
+	}
 
 	for path, api := range y.API.Paths {
 		if api.Timeout.Value < 0 {
@@ -354,6 +359,7 @@ func ymlToServerConfig(y *ymlFile) (*File, error) {
 		Log: &LogConfig{
 			ErrLevel:   errLevel,
 			AuditLevel: auditLevel,
+			LogLevel:   logLevel,
 		},
 		KeyStore: keystore,
 	}

kesconf/file.go

@@ -298,6 +298,9 @@ type LogConfig struct {
 	// Audit determines whether the KES server logs audit events to STDOUT.
 	// It does not en/disable audit logging in general.
 	AuditLevel slog.Level
+
+	// Log level for which to report KES diagnostic messages.
+	LogLevel slog.Level
 }
 
 // APIConfig is a structure that holds the API configuration