Consider replacing logging lib `sirupsen/logrus` with `log/slog`

[Nicolas-Peiffer]

Consider replacing logging lib https://github.com/sirupsen/logrus with golang standard library log/slog as described in https://go.dev/blog/slog.

Indeed, github.com/sirupsen/logrus latest version is from june 2023, and it is not clear if it is still maintained.
Whereas log/slog is from go standard library (https://cs.opensource.google/go/go/+/master:src/log/slog/;bpv=1). We can expect more maintainance.

However, one drawback is the syntax from log/slog is different from github.com/sirupsen/logrus, because log/slog is structured:

import "github.com/sirupsen/logrus"
// ...
logrus.Infof("Loaded P11 PIN from file: %v", a)

import "log/slog"
// ...
slog.Info("Loaded P11 PIN from file", slog.Any("pin", a))

// or

slog.Info("Loaded P11 PIN from file", "pin", a)

The output should look like this:

2025/01/01 16:27:19 INFO Loaded P11 PIN from file pin=a.value

or depending on the log/slog output handler format of log/slog (text, JSON):

time=2025-01-01T16:56:03.786-04:00 level=INFO msg="hello, world" user=jba

Maybe this could be done at the same time than enhancing the CLI with a --log-level flag, like suggested in #47

[Nicolas-Peiffer]

logrus supports additional features through hooks like: https://github.com/keepeye/logrus-filename

This feature can be convenient for debuging because it points to the file and the line which corresponds to the log message.

./k8s-kms-plugin serve  --debug
DEBU[0000] logrus log-level is set to: debug             line="cmd/root.go:83"
DEBU logrus format is set to: text                 line="cmd/root.go:96"
DEBU --socket flag is not used. Environment variable SOCKET is set to: masocketenvvar  line="cmd/root.go:214"
DEBU --p11-lib flag is not used. Environment variable P11_LIBRARY is set to: map11libenv  line="cmd/root.go:214"
DEBU --p11-label flag is not used. Environment variable P11_TOKEN is not set. Using default value:   line="cmd/root.go:218"
DEBU --p11-slot flag is not used. Environment variable P11_SLOT is not set. Using default value: 0  line="cmd/root.go:231"
DEBU --p11-pin flag is not used. Environment variable P11_PIN_FILE is not set. Using default value:   line="cmd/root.go:218"
DEBU initProvider: case p11 or softhsm             line="cmd/serve.go:179"
DEBU NewP11: &{kid:[97 51 55 56 48 55 99 100 45 54 100 49 97 45 52 100 55 53 45 56 49 51 97 45 101 49 50 48 102 51 48 49 55 54 102 55] cid:[] config:0xc00025e460 ctx:<nil> encryptors:map[] decryptors:map[] createKey:false k8sDekLabel:k8s-dek k8sHmacKeyLabel:k8s-hmac algorithm:A256GCM}  line="providers/p11.go:202"
DEBU NewP11: Config: &{Path:map11libenv TokenSerial: TokenLabel: SlotNumber:0x10a3080 Pin: MaxSessions:0 UserType:0 PoolWaitTimeout:0s LoginNotSupported:false UseGCMIVFromHSM:false GCMIVLength:0 GCMIVFromHSMControl:{SupplyIvForHSMGCMEncrypt:false SupplyIvForHSMGCMDecrypt:false} Tpm:false SecretKeyLabel: HmacKeyLabel:}  line="providers/p11.go:203"
DEBU NewP11: config.TokenLabel=                    line="providers/p11.go:204"
ERRO could not open PKCS#11                        line="providers/p11.go:208"
FATA failed to initialize provider: could not open PKCS#11  line="cmd/serve.go:114"

Below is the example corresponding to line="cmd/root.go:214":

---

This feature does not exist as is in log/slog. However, it might be possible to make an handler which can have the same feature.

package main

import (
	"context"
	"fmt"
	"log/slog"
	"os"
	"runtime"
	"strings"
)

type FilenameHandler struct {
	wrapped   slog.Handler
	Field     string
	Skip      int
	Formatter func(file, function string, line int) string
}

// NewFilenameHandler creates a new FilenameHandler wrapping an existing handler.
func NewFilenameHandler(handler slog.Handler, options ...func(*FilenameHandler)) *FilenameHandler {
	h := &FilenameHandler{
		wrapped: handler,
		Field:   "source",
		Skip:    0,
		Formatter: func(file, function string, line int) string {
			return fmt.Sprintf("%s:%d", file, line)
		},
	}
	for _, opt := range options {
		opt(h)
	}
	return h
}

// Enabled checks if the logging level is enabled.
func (h *FilenameHandler) Enabled(ctx context.Context, level slog.Level) bool {
	return h.wrapped.Enabled(ctx, level)
}

// Handle adds filename and line number attributes, then delegates to the wrapped handler.
func (h *FilenameHandler) Handle(ctx context.Context, record slog.Record) error {
	file, function, line := findCaller(h.Skip)
	formatted := h.Formatter(file, function, line)
	record.AddAttrs(slog.String(h.Field, formatted))
	return h.wrapped.Handle(ctx, record)
}

// WithAttrs returns a new handler with additional attributes.
func (h *FilenameHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
	return NewFilenameHandler(h.wrapped.WithAttrs(attrs))
}

// WithGroup returns a new handler with a group name.
func (h *FilenameHandler) WithGroup(name string) slog.Handler {
	return NewFilenameHandler(h.wrapped.WithGroup(name))
}

// findCaller retrieves the file, function name, and line number of the caller.
func findCaller(skip int) (string, string, int) {
	var (
		pc       uintptr
		file     string
		function string
		line     int
	)
	for i := 0; i < 10; i++ {
		pc, file, line, _ = runtime.Caller(skip + i)
		if !strings.Contains(file, "log/slog") { // Avoid internal calls
			break
		}
	}
	if pc != 0 {
		frames := runtime.CallersFrames([]uintptr{pc})
		frame, _ := frames.Next()
		function = frame.Function
	}

	// Trim file path for readability
	file = trimFilePath(file)
	return file, function, line
}

// trimFilePath trims the file path to show only the last two directories.
func trimFilePath(file string) string {
	n := 0
	for i := len(file) - 1; i > 0; i-- {
		if file[i] == '/' {
			n++
			if n >= 2 {
				return file[i+1:]
			}
		}
	}
	return file
}

func main() {
	// Create a default TextHandler
	handler := slog.NewTextHandler(os.Stdout, nil)

	// Wrap it with the FilenameHandler, customizing the field name
	handlerWithFilename := NewFilenameHandler(handler, func(h *FilenameHandler) {
		h.Field = "caller"
		h.Skip = 0
		h.Formatter = func(file, function string, line int) string {
			return fmt.Sprintf("%s:%s:%d", file, function, line)
		}
	})

	// Create a logger using the wrapped handler
	logger := slog.New(handlerWithFilename)
	newOutput := "ceci est un test"

	logger.Info("This is a test log", "clerandome", newOutput)
	logger.Info("This is a test log")
}

Code below looks like this

go build -o test-slog-filename-handler main.go

./test-slog-filename-handler

time=2025-01-23T13:55:44.231+01:00 level=INFO msg="This is a test log" clerandome="ceci est un test" caller=golang-deletemoi/main.go:main.findCaller:67
time=2025-01-23T13:55:44.231+01:00 level=INFO msg="This is a test log" caller=golang-deletemoi/main.go:main.findCaller:67

But this line main.go:main.findCaller:67 corresponds to pc, file, line, _ = runtime.Caller(skip + i). So this might need some adaptations.