Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Consider replacing logging lib sirupsen/logrus with log/slog #48

Open
Nicolas-Peiffer opened this issue Jan 20, 2025 · 1 comment
Open

Comments

@Nicolas-Peiffer
Copy link
Contributor

Nicolas-Peiffer commented Jan 20, 2025

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
Copy link
Contributor Author

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":

Image


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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

1 participant