From 6873ae17a21c1aa1c14f6c710f2b6d2a82e5e91d Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Florian=20Sch=C3=BCller?= <florian.schueller@redhat.com>
Date: Tue, 7 May 2024 10:39:57 +0200
Subject: [PATCH] logging: fix caller in echo_logrus

---
 cmd/image-builder/logging.go   |  5 +++
 internal/common/echo_logrus.go | 63 ++++++++++++++++++++++------------
 2 files changed, 47 insertions(+), 21 deletions(-)

diff --git a/cmd/image-builder/logging.go b/cmd/image-builder/logging.go
index 2de3e84c7..162ed42d5 100644
--- a/cmd/image-builder/logging.go
+++ b/cmd/image-builder/logging.go
@@ -2,6 +2,7 @@ package main
 
 import (
 	"context"
+	"runtime"
 	"strings"
 
 	"github.com/labstack/echo/v4"
@@ -41,6 +42,10 @@ func (h *ctxHook) Fire(e *logrus.Entry) error {
 		for k, v := range rd {
 			e.Data[k] = v
 		}
+		if e.Context.Value(common.LoggingFrameCtx) != nil {
+			frame := e.Context.Value(common.LoggingFrameCtx).(runtime.Frame)
+			e.Caller = &frame
+		}
 	}
 
 	return nil
diff --git a/internal/common/echo_logrus.go b/internal/common/echo_logrus.go
index a61b97c56..ab075fca5 100644
--- a/internal/common/echo_logrus.go
+++ b/internal/common/echo_logrus.go
@@ -4,11 +4,18 @@ import (
 	"context"
 	"encoding/json"
 	"io"
+	"runtime"
 
 	"github.com/labstack/gommon/log"
 	"github.com/sirupsen/logrus"
 )
 
+type ctxKey int
+
+const (
+	LoggingFrameCtx ctxKey = iota
+)
+
 // EchoLogrusLogger extend logrus.Logger
 type EchoLogrusLogger struct {
 	*logrus.Logger
@@ -39,6 +46,20 @@ 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) fixCaller() *logrus.Entry {
+	rpc := make([]uintptr, 1)
+	// fixCaller 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, LoggingFrameCtx, frame)
+	return l.Logger.WithContext(frameOverride)
+}
+
 func (l *EchoLogrusLogger) Output() io.Writer {
 	return l.Out
 }
@@ -66,11 +87,11 @@ func (l *EchoLogrusLogger) SetPrefix(p string) {
 }
 
 func (l *EchoLogrusLogger) Print(i ...interface{}) {
-	l.Logger.WithContext(l.Ctx).Print(i...)
+	l.fixCaller().Print(i...)
 }
 
 func (l *EchoLogrusLogger) Printf(format string, args ...interface{}) {
-	l.Logger.WithContext(l.Ctx).Printf(format, args...)
+	l.fixCaller().Printf(format, args...)
 }
 
 func (l *EchoLogrusLogger) Printj(j log.JSON) {
@@ -78,15 +99,15 @@ func (l *EchoLogrusLogger) Printj(j log.JSON) {
 	if err != nil {
 		panic(err)
 	}
-	l.Logger.WithContext(l.Ctx).Println(string(b))
+	l.fixCaller().Println(string(b))
 }
 
 func (l *EchoLogrusLogger) Debug(i ...interface{}) {
-	l.Logger.WithContext(l.Ctx).Debug(i...)
+	l.fixCaller().Debug(i...)
 }
 
 func (l *EchoLogrusLogger) Debugf(format string, args ...interface{}) {
-	l.Logger.WithContext(l.Ctx).Debugf(format, args...)
+	l.fixCaller().Debugf(format, args...)
 }
 
 func (l *EchoLogrusLogger) Debugj(j log.JSON) {
@@ -94,15 +115,15 @@ func (l *EchoLogrusLogger) Debugj(j log.JSON) {
 	if err != nil {
 		panic(err)
 	}
-	l.Logger.WithContext(l.Ctx).Debugln(string(b))
+	l.fixCaller().Debugln(string(b))
 }
 
 func (l *EchoLogrusLogger) Info(i ...interface{}) {
-	l.Logger.WithContext(l.Ctx).Info(i...)
+	l.fixCaller().Info(i...)
 }
 
 func (l *EchoLogrusLogger) Infof(format string, args ...interface{}) {
-	l.Logger.WithContext(l.Ctx).Infof(format, args...)
+	l.fixCaller().Infof(format, args...)
 }
 
 func (l *EchoLogrusLogger) Infoj(j log.JSON) {
@@ -110,15 +131,15 @@ func (l *EchoLogrusLogger) Infoj(j log.JSON) {
 	if err != nil {
 		panic(err)
 	}
-	l.Logger.WithContext(l.Ctx).Infoln(string(b))
+	l.fixCaller().Infoln(string(b))
 }
 
 func (l *EchoLogrusLogger) Warn(i ...interface{}) {
-	l.Logger.WithContext(l.Ctx).Warn(i...)
+	l.fixCaller().Warn(i...)
 }
 
 func (l *EchoLogrusLogger) Warnf(format string, args ...interface{}) {
-	l.Logger.WithContext(l.Ctx).Warnf(format, args...)
+	l.fixCaller().Warnf(format, args...)
 }
 
 func (l *EchoLogrusLogger) Warnj(j log.JSON) {
@@ -126,15 +147,15 @@ func (l *EchoLogrusLogger) Warnj(j log.JSON) {
 	if err != nil {
 		panic(err)
 	}
-	l.Logger.WithContext(l.Ctx).Warnln(string(b))
+	l.fixCaller().Warnln(string(b))
 }
 
 func (l *EchoLogrusLogger) Error(i ...interface{}) {
-	l.Logger.WithContext(l.Ctx).Error(i...)
+	l.fixCaller().Error(i...)
 }
 
 func (l *EchoLogrusLogger) Errorf(format string, args ...interface{}) {
-	l.Logger.WithContext(l.Ctx).Errorf(format, args...)
+	l.fixCaller().Errorf(format, args...)
 }
 
 func (l *EchoLogrusLogger) Errorj(j log.JSON) {
@@ -142,15 +163,15 @@ func (l *EchoLogrusLogger) Errorj(j log.JSON) {
 	if err != nil {
 		panic(err)
 	}
-	l.Logger.WithContext(l.Ctx).Errorln(string(b))
+	l.fixCaller().Errorln(string(b))
 }
 
 func (l *EchoLogrusLogger) Fatal(i ...interface{}) {
-	l.Logger.WithContext(l.Ctx).Fatal(i...)
+	l.fixCaller().Fatal(i...)
 }
 
 func (l *EchoLogrusLogger) Fatalf(format string, args ...interface{}) {
-	l.Logger.WithContext(l.Ctx).Fatalf(format, args...)
+	l.fixCaller().Fatalf(format, args...)
 }
 
 func (l *EchoLogrusLogger) Fatalj(j log.JSON) {
@@ -158,15 +179,15 @@ func (l *EchoLogrusLogger) Fatalj(j log.JSON) {
 	if err != nil {
 		panic(err)
 	}
-	l.Logger.WithContext(l.Ctx).Fatalln(string(b))
+	l.fixCaller().Fatalln(string(b))
 }
 
 func (l *EchoLogrusLogger) Panic(i ...interface{}) {
-	l.Logger.WithContext(l.Ctx).Panic(i...)
+	l.fixCaller().Panic(i...)
 }
 
 func (l *EchoLogrusLogger) Panicf(format string, args ...interface{}) {
-	l.Logger.WithContext(l.Ctx).Panicf(format, args...)
+	l.fixCaller().Panicf(format, args...)
 }
 
 func (l *EchoLogrusLogger) Panicj(j log.JSON) {
@@ -174,5 +195,5 @@ func (l *EchoLogrusLogger) Panicj(j log.JSON) {
 	if err != nil {
 		panic(err)
 	}
-	l.Logger.WithContext(l.Ctx).Panicln(string(b))
+	l.fixCaller().Panicln(string(b))
 }