logging: fix caller in echo_logrus and simple logger

internal/common/echo_logrus.go

@@ -1,20 +1,26 @@
 package common
 
 import (
+	"context"
 	"encoding/json"
 	"io"
+	"runtime"
 
 	"github.com/labstack/gommon/log"
 	"github.com/sirupsen/logrus"
+
+	"github.com/osbuild/osbuild-composer/internal/common/slogger"
 )
 
 // EchoLogrusLogger extend logrus.Logger
 type EchoLogrusLogger struct {
 	*logrus.Logger
+	Ctx context.Context
 }
 
 var commonLogger = &EchoLogrusLogger{
 	Logger: logrus.StandardLogger(),
+	Ctx:    context.Background(),
 }
 
 func Logger() *EchoLogrusLogger {
@@ -36,6 +42,51 @@ func toEchoLevel(level logrus.Level) log.Lvl {
 	return log.OFF
 }
 
+// add the context and caller to the fields
+// as logrus will report "echo_logrus.go" otherwise
+func (l *EchoLogrusLogger) logWithCaller() *logrus.Entry {
+	// this function is necessary as logrus would report
+	// the location of the wrapper function by default
+	rpc := make([]uintptr, 1)
+	// logWithCaller is always 3 frames below the calling context
+	n := runtime.Callers(3, rpc[:])
+	if n < 1 {
+		return l.Logger.WithContext(l.Ctx)
+	}
+	frame, _ := runtime.CallersFrames(rpc).Next()
+	frameOverride := context.WithValue(l.Ctx, slogger.LoggingFrameCtx, frame)
+	return l.Logger.WithContext(frameOverride)
+}
+
+type ctxHook struct {
+}
+
+func (h *ctxHook) Levels() []logrus.Level {
+	return []logrus.Level{
+		logrus.DebugLevel,
+		logrus.InfoLevel,
+		logrus.WarnLevel,
+		logrus.ErrorLevel,
+		logrus.FatalLevel,
+		logrus.PanicLevel,
+	}
+}
+
+func (h *ctxHook) Fire(e *logrus.Entry) error {
+	if e.Context != nil {
+		if e.Context.Value(slogger.LoggingFrameCtx) != nil {
+			frame := e.Context.Value(slogger.LoggingFrameCtx).(runtime.Frame)
+			e.Caller = &frame
+		}
+	}
+
+	return nil
+}
+
+func init() {
+	commonLogger.Logger.AddHook(&ctxHook{})
+}
+
 func (l *EchoLogrusLogger) Output() io.Writer {
 	return l.Out
 }
@@ -63,113 +114,113 @@ func (l *EchoLogrusLogger) SetPrefix(p string) {
 }
 
 func (l *EchoLogrusLogger) Print(i ...interface{}) {
-	l.Logger.Print(i...)
+	l.logWithCaller().Print(i...)
 }
 
 func (l *EchoLogrusLogger) Printf(format string, args ...interface{}) {
-	l.Logger.Printf(format, args...)
+	l.logWithCaller().Printf(format, args...)
 }
 
 func (l *EchoLogrusLogger) Printj(j log.JSON) {
 	b, err := json.Marshal(j)
 	if err != nil {
 		panic(err)
 	}
-	l.Logger.Println(string(b))
+	l.logWithCaller().Println(string(b))
 }
 
 func (l *EchoLogrusLogger) Debug(i ...interface{}) {
-	l.Logger.Debug(i...)
+	l.logWithCaller().Debug(i...)
 }
 
 func (l *EchoLogrusLogger) Debugf(format string, args ...interface{}) {
-	l.Logger.Debugf(format, args...)
+	l.logWithCaller().Debugf(format, args...)
 }
 
 func (l *EchoLogrusLogger) Debugj(j log.JSON) {
 	b, err := json.Marshal(j)
 	if err != nil {
 		panic(err)
 	}
-	l.Logger.Debugln(string(b))
+	l.logWithCaller().Debugln(string(b))
 }
 
 func (l *EchoLogrusLogger) Info(i ...interface{}) {
-	l.Logger.Info(i...)
+	l.logWithCaller().Info(i...)
 }
 
 func (l *EchoLogrusLogger) Infof(format string, args ...interface{}) {
-	l.Logger.Infof(format, args...)
+	l.logWithCaller().Infof(format, args...)
 }
 
 func (l *EchoLogrusLogger) Infoj(j log.JSON) {
 	b, err := json.Marshal(j)
 	if err != nil {
 		panic(err)
 	}
-	l.Logger.Infoln(string(b))
+	l.logWithCaller().Infoln(string(b))
 }
 
 func (l *EchoLogrusLogger) Warn(i ...interface{}) {
-	l.Logger.Warn(i...)
+	l.logWithCaller().Warn(i...)
 }
 
 func (l *EchoLogrusLogger) Warnf(format string, args ...interface{}) {
-	l.Logger.Warnf(format, args...)
+	l.logWithCaller().Warnf(format, args...)
 }
 
 func (l *EchoLogrusLogger) Warnj(j log.JSON) {
 	b, err := json.Marshal(j)
 	if err != nil {
 		panic(err)
 	}
-	l.Logger.Warnln(string(b))
+	l.logWithCaller().Warnln(string(b))
 }
 
 func (l *EchoLogrusLogger) Error(i ...interface{}) {
-	l.Logger.Error(i...)
+	l.logWithCaller().Error(i...)
 }
 
 func (l *EchoLogrusLogger) Errorf(format string, args ...interface{}) {
-	l.Logger.Errorf(format, args...)
+	l.logWithCaller().Errorf(format, args...)
 }
 
 func (l *EchoLogrusLogger) Errorj(j log.JSON) {
 	b, err := json.Marshal(j)
 	if err != nil {
 		panic(err)
 	}
-	l.Logger.Errorln(string(b))
+	l.logWithCaller().Errorln(string(b))
 }
 
 func (l *EchoLogrusLogger) Fatal(i ...interface{}) {
-	l.Logger.Fatal(i...)
+	l.logWithCaller().Fatal(i...)
 }
 
 func (l *EchoLogrusLogger) Fatalf(format string, args ...interface{}) {
-	l.Logger.Fatalf(format, args...)
+	l.logWithCaller().Fatalf(format, args...)
 }
 
 func (l *EchoLogrusLogger) Fatalj(j log.JSON) {
 	b, err := json.Marshal(j)
 	if err != nil {
 		panic(err)
 	}
-	l.Logger.Fatalln(string(b))
+	l.logWithCaller().Fatalln(string(b))
 }
 
 func (l *EchoLogrusLogger) Panic(i ...interface{}) {
-	l.Logger.Panic(i...)
+	l.logWithCaller().Panic(i...)
 }
 
 func (l *EchoLogrusLogger) Panicf(format string, args ...interface{}) {
-	l.Logger.Panicf(format, args...)
+	l.logWithCaller().Panicf(format, args...)
 }
 
 func (l *EchoLogrusLogger) Panicj(j log.JSON) {
 	b, err := json.Marshal(j)
 	if err != nil {
 		panic(err)
 	}
-	l.Logger.Panicln(string(b))
+	l.logWithCaller().Panicln(string(b))
 }

internal/common/slogger/logrus.go

@@ -1,16 +1,67 @@
 package slogger
 
 import (
+	"context"
 	"github.com/osbuild/osbuild-composer/pkg/jobqueue"
 	"github.com/sirupsen/logrus"
+	"runtime"
 )
 
 type simpleLogrus struct {
 	logger *logrus.Logger
 }
 
 func NewLogrusLogger(logger *logrus.Logger) jobqueue.SimpleLogger {
-	return &simpleLogrus{logger: logger}
+	newLogger := &simpleLogrus{logger: logger}
+	logger.AddHook(&ctxHook{})
+	return newLogger
+}
+
+type ctxKey int
+
+const (
+	LoggingFrameLogrusCtx ctxKey = iota
+	LoggingFrameCtx       ctxKey = iota
+)
+
+type ctxHook struct {
+}
+
+func (h *ctxHook) Levels() []logrus.Level {
+	return []logrus.Level{
+		logrus.DebugLevel,
+		logrus.InfoLevel,
+		logrus.WarnLevel,
+		logrus.ErrorLevel,
+		logrus.FatalLevel,
+		logrus.PanicLevel,
+	}
+}
+
+func (h *ctxHook) Fire(e *logrus.Entry) error {
+	if e.Context != nil {
+		if e.Context.Value(LoggingFrameLogrusCtx) != nil {
+			frame := e.Context.Value(LoggingFrameLogrusCtx).(runtime.Frame)
+			e.Caller = &frame
+		}
+	}
+
+	return nil
+}
+
+func (l *simpleLogrus) logWithCaller() *logrus.Entry {
+	// this function is necessary as logrus would report
+	// the location of the wrapper function by default
+	ctx := context.Background()
+	rpc := make([]uintptr, 1)
+	// logWithCaller is always 4 frames below the calling context
+	n := runtime.Callers(4, rpc[:])
+	if n < 1 {
+		return l.logger.WithContext(ctx)
+	}
+	frame, _ := runtime.CallersFrames(rpc).Next()
+	frameOverride := context.WithValue(ctx, LoggingFrameLogrusCtx, frame)
+	return l.logger.WithContext(frameOverride)
 }
 
 func (s *simpleLogrus) log(level logrus.Level, err error, msg string, args ...string) {
@@ -26,7 +77,7 @@ func (s *simpleLogrus) log(level logrus.Level, err error, msg string, args ...st
 	if err != nil {
 		fields["error"] = err.Error()
 	}
-	s.logger.WithFields(fields).Log(level, msg)
+	s.logWithCaller().WithFields(fields).Log(level, msg)
 }
 
 func (s *simpleLogrus) Info(msg string, args ...string) {