From 8e7e1bac74743372a3de5b6d73e145ef95610637 Mon Sep 17 00:00:00 2001 From: Lukas Zapletal Date: Mon, 6 May 2024 20:19:06 +0200 Subject: [PATCH 1/2] echo_logrus: use std context for fields Signed-off-by: Lukas Zapletal --- cmd/image-builder/logging.go | 26 +++++++++++++------ cmd/image-builder/main.go | 3 ++- internal/common/echo_logrus.go | 46 ++++++++++++++++------------------ 3 files changed, 43 insertions(+), 32 deletions(-) diff --git a/cmd/image-builder/logging.go b/cmd/image-builder/logging.go index d9207aa9c..2de3e84c7 100644 --- a/cmd/image-builder/logging.go +++ b/cmd/image-builder/logging.go @@ -15,6 +15,7 @@ type ctxKey int const ( requestIdCtx ctxKey = iota insightsRequestIdCtx ctxKey = iota + requestDataCtx ctxKey = iota ) // Use request id from the standard context and add it to the message as a field. @@ -36,6 +37,10 @@ func (h *ctxHook) Fire(e *logrus.Entry) error { if e.Context != nil { e.Data["request_id"] = e.Context.Value(requestIdCtx) e.Data["insights_id"] = e.Context.Value(insightsRequestIdCtx) + rd := e.Context.Value(requestDataCtx).(logrus.Fields) + for k, v := range rd { + e.Data[k] = v + } } return nil @@ -59,27 +64,34 @@ func requestIdExtractMiddleware(next echo.HandlerFunc) echo.HandlerFunc { iid = random.String(12) } + // create fields stored with every log statement + rd := logrus.Fields{ + "method": c.Request().Method, + "path": c.Path(), + } + for _, key := range c.ParamNames() { + // protect existing and the most important fields + if _, ok := rd[key]; !(ok || key == "msg" || key == "level") { + rd[key] = c.Param(key) + } + } + // store it in a standard context ctx := c.Request().Context() ctx = context.WithValue(ctx, requestIdCtx, rid) ctx = context.WithValue(ctx, insightsRequestIdCtx, iid) + ctx = context.WithValue(ctx, requestDataCtx, rd) c.SetRequest(c.Request().WithContext(ctx)) - f := logrus.Fields{"method": c.Request().Method, "path": c.Path()} - for _, key := range c.ParamNames() { - f[key] = c.Param(key) - } - // and set echo logger to be context logger ctxLogger := logrus.StandardLogger() c.SetLogger(&common.EchoLogrusLogger{ Logger: ctxLogger, Ctx: ctx, - Fields: f, }) if !SkipPath(c.Path()) { - c.Logger().Debugf("Started request") + ctxLogger.WithContext(ctx).WithFields(rd).Debugf("Started request") } return next(c) diff --git a/cmd/image-builder/main.go b/cmd/image-builder/main.go index a303d1a79..b2174676d 100644 --- a/cmd/image-builder/main.go +++ b/cmd/image-builder/main.go @@ -154,7 +154,8 @@ func main() { if values.Error != nil { fields["error"] = values.Error } - logrus.WithFields(fields).Infof("Processed request %s %s", values.Method, values.URI) + logrus.WithContext(c.Request().Context()). + WithFields(fields).Infof("Processed request %s %s", values.Method, values.URI) return nil }, diff --git a/internal/common/echo_logrus.go b/internal/common/echo_logrus.go index 9294caff0..a61b97c56 100644 --- a/internal/common/echo_logrus.go +++ b/internal/common/echo_logrus.go @@ -12,14 +12,12 @@ import ( // EchoLogrusLogger extend logrus.Logger type EchoLogrusLogger struct { *logrus.Logger - Ctx context.Context - Fields logrus.Fields + Ctx context.Context } var commonLogger = &EchoLogrusLogger{ Logger: logrus.StandardLogger(), Ctx: context.Background(), - Fields: logrus.Fields{}, } func Logger() *EchoLogrusLogger { @@ -68,11 +66,11 @@ func (l *EchoLogrusLogger) SetPrefix(p string) { } func (l *EchoLogrusLogger) Print(i ...interface{}) { - l.Logger.WithContext(l.Ctx).WithFields(l.Fields).Print(i...) + l.Logger.WithContext(l.Ctx).Print(i...) } func (l *EchoLogrusLogger) Printf(format string, args ...interface{}) { - l.Logger.WithContext(l.Ctx).WithFields(l.Fields).Printf(format, args...) + l.Logger.WithContext(l.Ctx).Printf(format, args...) } func (l *EchoLogrusLogger) Printj(j log.JSON) { @@ -80,15 +78,15 @@ func (l *EchoLogrusLogger) Printj(j log.JSON) { if err != nil { panic(err) } - l.Logger.WithContext(l.Ctx).WithFields(l.Fields).Println(string(b)) + l.Logger.WithContext(l.Ctx).Println(string(b)) } func (l *EchoLogrusLogger) Debug(i ...interface{}) { - l.Logger.WithContext(l.Ctx).WithFields(l.Fields).Debug(i...) + l.Logger.WithContext(l.Ctx).Debug(i...) } func (l *EchoLogrusLogger) Debugf(format string, args ...interface{}) { - l.Logger.WithContext(l.Ctx).WithFields(l.Fields).Debugf(format, args...) + l.Logger.WithContext(l.Ctx).Debugf(format, args...) } func (l *EchoLogrusLogger) Debugj(j log.JSON) { @@ -96,15 +94,15 @@ func (l *EchoLogrusLogger) Debugj(j log.JSON) { if err != nil { panic(err) } - l.Logger.WithContext(l.Ctx).WithFields(l.Fields).Debugln(string(b)) + l.Logger.WithContext(l.Ctx).Debugln(string(b)) } func (l *EchoLogrusLogger) Info(i ...interface{}) { - l.Logger.WithContext(l.Ctx).WithFields(l.Fields).Info(i...) + l.Logger.WithContext(l.Ctx).Info(i...) } func (l *EchoLogrusLogger) Infof(format string, args ...interface{}) { - l.Logger.WithContext(l.Ctx).WithFields(l.Fields).Infof(format, args...) + l.Logger.WithContext(l.Ctx).Infof(format, args...) } func (l *EchoLogrusLogger) Infoj(j log.JSON) { @@ -112,15 +110,15 @@ func (l *EchoLogrusLogger) Infoj(j log.JSON) { if err != nil { panic(err) } - l.Logger.WithContext(l.Ctx).WithFields(l.Fields).Infoln(string(b)) + l.Logger.WithContext(l.Ctx).Infoln(string(b)) } func (l *EchoLogrusLogger) Warn(i ...interface{}) { - l.Logger.WithContext(l.Ctx).WithFields(l.Fields).Warn(i...) + l.Logger.WithContext(l.Ctx).Warn(i...) } func (l *EchoLogrusLogger) Warnf(format string, args ...interface{}) { - l.Logger.WithContext(l.Ctx).WithFields(l.Fields).Warnf(format, args...) + l.Logger.WithContext(l.Ctx).Warnf(format, args...) } func (l *EchoLogrusLogger) Warnj(j log.JSON) { @@ -128,15 +126,15 @@ func (l *EchoLogrusLogger) Warnj(j log.JSON) { if err != nil { panic(err) } - l.Logger.WithContext(l.Ctx).WithFields(l.Fields).Warnln(string(b)) + l.Logger.WithContext(l.Ctx).Warnln(string(b)) } func (l *EchoLogrusLogger) Error(i ...interface{}) { - l.Logger.WithContext(l.Ctx).WithFields(l.Fields).Error(i...) + l.Logger.WithContext(l.Ctx).Error(i...) } func (l *EchoLogrusLogger) Errorf(format string, args ...interface{}) { - l.Logger.WithContext(l.Ctx).WithFields(l.Fields).Errorf(format, args...) + l.Logger.WithContext(l.Ctx).Errorf(format, args...) } func (l *EchoLogrusLogger) Errorj(j log.JSON) { @@ -144,15 +142,15 @@ func (l *EchoLogrusLogger) Errorj(j log.JSON) { if err != nil { panic(err) } - l.Logger.WithContext(l.Ctx).WithFields(l.Fields).Errorln(string(b)) + l.Logger.WithContext(l.Ctx).Errorln(string(b)) } func (l *EchoLogrusLogger) Fatal(i ...interface{}) { - l.Logger.WithContext(l.Ctx).WithFields(l.Fields).Fatal(i...) + l.Logger.WithContext(l.Ctx).Fatal(i...) } func (l *EchoLogrusLogger) Fatalf(format string, args ...interface{}) { - l.Logger.WithContext(l.Ctx).WithFields(l.Fields).Fatalf(format, args...) + l.Logger.WithContext(l.Ctx).Fatalf(format, args...) } func (l *EchoLogrusLogger) Fatalj(j log.JSON) { @@ -160,15 +158,15 @@ func (l *EchoLogrusLogger) Fatalj(j log.JSON) { if err != nil { panic(err) } - l.Logger.WithContext(l.Ctx).WithFields(l.Fields).Fatalln(string(b)) + l.Logger.WithContext(l.Ctx).Fatalln(string(b)) } func (l *EchoLogrusLogger) Panic(i ...interface{}) { - l.Logger.WithContext(l.Ctx).WithFields(l.Fields).Panic(i...) + l.Logger.WithContext(l.Ctx).Panic(i...) } func (l *EchoLogrusLogger) Panicf(format string, args ...interface{}) { - l.Logger.WithContext(l.Ctx).WithFields(l.Fields).Panicf(format, args...) + l.Logger.WithContext(l.Ctx).Panicf(format, args...) } func (l *EchoLogrusLogger) Panicj(j log.JSON) { @@ -176,5 +174,5 @@ func (l *EchoLogrusLogger) Panicj(j log.JSON) { if err != nil { panic(err) } - l.Logger.WithContext(l.Ctx).WithFields(l.Fields).Panicln(string(b)) + l.Logger.WithContext(l.Ctx).Panicln(string(b)) } From bf2ad389a3a0a1dc236e091cc106ba4b51ee8951 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Florian=20Sch=C3=BCller?= Date: Tue, 7 May 2024 10:39:57 +0200 Subject: [PATCH 2/2] logging: fix caller in echo_logrus --- internal/common/echo_logrus.go | 91 ++++++++++++++++++++++++++-------- 1 file changed, 70 insertions(+), 21 deletions(-) diff --git a/internal/common/echo_logrus.go b/internal/common/echo_logrus.go index a61b97c56..639f46727 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,48 @@ 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) +} + +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(LoggingFrameCtx) != nil { + frame := e.Context.Value(LoggingFrameCtx).(runtime.Frame) + e.Caller = &frame + } + } + return nil +} + +func init() { + commonLogger.Logger.AddHook(&ctxHook{}) +} + func (l *EchoLogrusLogger) Output() io.Writer { return l.Out } @@ -66,11 +115,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 +127,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 +143,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 +159,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 +175,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 +191,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 +207,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 +223,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)) }