diff --git a/cmd/osbuild-composer/main.go b/cmd/osbuild-composer/main.go index d6047f61b..3bd6dd600 100644 --- a/cmd/osbuild-composer/main.go +++ b/cmd/osbuild-composer/main.go @@ -50,6 +50,8 @@ func main() { logLevel, err := logrus.ParseLevel(config.LogLevel) logrus.SetReportCaller(true) + // Add context hook to log operation_id and external_id + logrus.AddHook(&common.ContextHook{}) if err == nil { logrus.SetLevel(logLevel) diff --git a/internal/cloudapi/v2/server.go b/internal/cloudapi/v2/server.go index 9a51d24ca..ac56719da 100644 --- a/internal/cloudapi/v2/server.go +++ b/internal/cloudapi/v2/server.go @@ -87,10 +87,37 @@ func (s *Server) Handler(path string) http.Handler { e := echo.New() e.Binder = binder{} e.HTTPErrorHandler = s.HTTPErrorHandler - e.Pre(common.OperationIDMiddleware) - e.Use(middleware.Recover()) e.Logger = common.Logger() + // OperationIDMiddleware - generates OperationID random string and puts it into the contexts + // ExternalIDMiddleware - extracts ID from HTTP header and puts it into the contexts + // LoggerMiddleware - creates context-aware logger for each request + e.Pre(common.OperationIDMiddleware, common.ExternalIDMiddleware, common.LoggerMiddleware) + e.Use(middleware.Recover()) + + e.Use(middleware.RequestLoggerWithConfig(middleware.RequestLoggerConfig{ + LogURI: true, + LogStatus: true, + LogLatency: true, + LogMethod: true, + LogValuesFunc: func(c echo.Context, values middleware.RequestLoggerValues) error { + fields := logrus.Fields{ + "uri": values.URI, + "method": values.Method, + "status": values.Status, + "latency_ms": values.Latency.Milliseconds(), + "operation_id": c.Get(common.OperationIDKey), + "external_id": c.Get(common.ExternalIDKey), + } + if values.Error != nil { + fields["error"] = values.Error + } + logrus.WithFields(fields).Infof("Processed request %s %s", values.Method, values.URI) + + return nil + }, + })) + if sentry.CurrentHub().Client() == nil { logrus.Warn("Sentry/Glitchtip not initialized, echo middleware was not enabled") } else { diff --git a/internal/common/context_hook.go b/internal/common/context_hook.go new file mode 100644 index 000000000..294b2867e --- /dev/null +++ b/internal/common/context_hook.go @@ -0,0 +1,33 @@ +package common + +import ( + "github.com/sirupsen/logrus" +) + +type ContextHook struct{} + +func (h *ContextHook) Levels() []logrus.Level { + return []logrus.Level{ + logrus.DebugLevel, + logrus.InfoLevel, + logrus.WarnLevel, + logrus.ErrorLevel, + logrus.FatalLevel, + logrus.PanicLevel, + } +} + +func (h *ContextHook) Fire(e *logrus.Entry) error { + if e.Context == nil { + return nil + } + + if val := e.Context.Value(operationIDKeyCtx); val != nil { + e.Data["operation_id"] = val + } + if val := e.Context.Value(externalIDKeyCtx); val != nil { + e.Data["external_id"] = val + } + + return nil +} diff --git a/internal/common/echo_logrus.go b/internal/common/echo_logrus.go index 6871f8713..198ce1731 100644 --- a/internal/common/echo_logrus.go +++ b/internal/common/echo_logrus.go @@ -1,39 +1,42 @@ package common import ( + "context" "encoding/json" "io" - "github.com/labstack/gommon/log" + lslog "github.com/labstack/gommon/log" "github.com/sirupsen/logrus" ) // EchoLogrusLogger extend logrus.Logger type EchoLogrusLogger struct { *logrus.Logger + Ctx context.Context } var commonLogger = &EchoLogrusLogger{ Logger: logrus.StandardLogger(), + Ctx: context.Background(), } func Logger() *EchoLogrusLogger { return commonLogger } -func toEchoLevel(level logrus.Level) log.Lvl { +func toEchoLevel(level logrus.Level) lslog.Lvl { switch level { case logrus.DebugLevel: - return log.DEBUG + return lslog.DEBUG case logrus.InfoLevel: - return log.INFO + return lslog.INFO case logrus.WarnLevel: - return log.WARN + return lslog.WARN case logrus.ErrorLevel: - return log.ERROR + return lslog.ERROR } - return log.OFF + return lslog.OFF } func (l *EchoLogrusLogger) Output() io.Writer { @@ -44,11 +47,11 @@ func (l *EchoLogrusLogger) SetOutput(w io.Writer) { // disable operations that would change behavior of global logrus logger. } -func (l *EchoLogrusLogger) Level() log.Lvl { +func (l *EchoLogrusLogger) Level() lslog.Lvl { return toEchoLevel(l.Logger.Level) } -func (l *EchoLogrusLogger) SetLevel(v log.Lvl) { +func (l *EchoLogrusLogger) SetLevel(v lslog.Lvl) { // disable operations that would change behavior of global logrus logger. } @@ -63,113 +66,117 @@ func (l *EchoLogrusLogger) SetPrefix(p string) { } func (l *EchoLogrusLogger) Print(i ...interface{}) { - l.Logger.Print(i...) + l.Logger.WithContext(l.Ctx).Print(i...) } func (l *EchoLogrusLogger) Printf(format string, args ...interface{}) { - l.Logger.Printf(format, args...) + l.Logger.WithContext(l.Ctx).Printf(format, args...) } -func (l *EchoLogrusLogger) Printj(j log.JSON) { +func (l *EchoLogrusLogger) Printj(j lslog.JSON) { b, err := json.Marshal(j) if err != nil { panic(err) } - l.Logger.Println(string(b)) + l.Logger.WithContext(l.Ctx).Println(string(b)) } func (l *EchoLogrusLogger) Debug(i ...interface{}) { - l.Logger.Debug(i...) + l.Logger.WithContext(l.Ctx).Debug(i...) } func (l *EchoLogrusLogger) Debugf(format string, args ...interface{}) { - l.Logger.Debugf(format, args...) + l.Logger.WithContext(l.Ctx).Debugf(format, args...) } -func (l *EchoLogrusLogger) Debugj(j log.JSON) { +func (l *EchoLogrusLogger) Debugj(j lslog.JSON) { b, err := json.Marshal(j) if err != nil { panic(err) } - l.Logger.Debugln(string(b)) + l.Logger.WithContext(l.Ctx).Debugln(string(b)) } func (l *EchoLogrusLogger) Info(i ...interface{}) { - l.Logger.Info(i...) + l.Logger.WithContext(l.Ctx).Info(i...) } func (l *EchoLogrusLogger) Infof(format string, args ...interface{}) { - l.Logger.Infof(format, args...) + l.Logger.WithContext(l.Ctx).Infof(format, args...) } -func (l *EchoLogrusLogger) Infoj(j log.JSON) { +func (l *EchoLogrusLogger) Infoj(j lslog.JSON) { b, err := json.Marshal(j) if err != nil { panic(err) } - l.Logger.Infoln(string(b)) + l.Logger.WithContext(l.Ctx).Infoln(string(b)) } func (l *EchoLogrusLogger) Warn(i ...interface{}) { - l.Logger.Warn(i...) + l.Logger.WithContext(l.Ctx).Warn(i...) } func (l *EchoLogrusLogger) Warnf(format string, args ...interface{}) { - l.Logger.Warnf(format, args...) + l.Logger.WithContext(l.Ctx).Warnf(format, args...) } -func (l *EchoLogrusLogger) Warnj(j log.JSON) { +func (l *EchoLogrusLogger) Warnj(j lslog.JSON) { b, err := json.Marshal(j) if err != nil { panic(err) } - l.Logger.Warnln(string(b)) + l.Logger.WithContext(l.Ctx).Warnln(string(b)) } func (l *EchoLogrusLogger) Error(i ...interface{}) { - l.Logger.Error(i...) + l.Logger.WithContext(l.Ctx).Error(i...) } func (l *EchoLogrusLogger) Errorf(format string, args ...interface{}) { - l.Logger.Errorf(format, args...) + l.Logger.WithContext(l.Ctx).Errorf(format, args...) } -func (l *EchoLogrusLogger) Errorj(j log.JSON) { +func (l *EchoLogrusLogger) Errorj(j lslog.JSON) { b, err := json.Marshal(j) if err != nil { panic(err) } - l.Logger.Errorln(string(b)) + l.Logger.WithContext(l.Ctx).Errorln(string(b)) } func (l *EchoLogrusLogger) Fatal(i ...interface{}) { - l.Logger.Fatal(i...) + l.Logger.WithContext(l.Ctx).Fatal(i...) } func (l *EchoLogrusLogger) Fatalf(format string, args ...interface{}) { - l.Logger.Fatalf(format, args...) + l.Logger.WithContext(l.Ctx).Fatalf(format, args...) } -func (l *EchoLogrusLogger) Fatalj(j log.JSON) { +func (l *EchoLogrusLogger) Fatalj(j lslog.JSON) { b, err := json.Marshal(j) if err != nil { panic(err) } - l.Logger.Fatalln(string(b)) + l.Logger.WithContext(l.Ctx).Fatalln(string(b)) } func (l *EchoLogrusLogger) Panic(i ...interface{}) { - l.Logger.Panic(i...) + l.Logger.WithContext(l.Ctx).Panic(i...) } func (l *EchoLogrusLogger) Panicf(format string, args ...interface{}) { - l.Logger.Panicf(format, args...) + l.Logger.WithContext(l.Ctx).Panicf(format, args...) } -func (l *EchoLogrusLogger) Panicj(j log.JSON) { +func (l *EchoLogrusLogger) Panicj(j lslog.JSON) { b, err := json.Marshal(j) if err != nil { panic(err) } - l.Logger.Panicln(string(b)) + l.Logger.WithContext(l.Ctx).Panicln(string(b)) +} + +func (l *EchoLogrusLogger) Write(p []byte) (n int, err error) { + return l.Logger.WithContext(l.Ctx).Writer().Write(p) } diff --git a/internal/common/external_id.go b/internal/common/external_id.go new file mode 100644 index 000000000..04038129c --- /dev/null +++ b/internal/common/external_id.go @@ -0,0 +1,30 @@ +package common + +import ( + "context" + "strings" + + "github.com/labstack/echo/v4" +) + +const ExternalIDKey string = "externalID" +const externalIDKeyCtx ctxKey = ctxKey(ExternalIDKey) + +// Extracts HTTP header X-External-Id and sets it as a request context value +func ExternalIDMiddleware(next echo.HandlerFunc) echo.HandlerFunc { + return func(c echo.Context) error { + eid := c.Request().Header.Get("X-External-Id") + if eid == "" { + return next(c) + } + + eid = strings.TrimSuffix(eid, "\n") + c.Set(ExternalIDKey, eid) + + ctx := c.Request().Context() + ctx = context.WithValue(ctx, externalIDKeyCtx, eid) + c.SetRequest(c.Request().WithContext(ctx)) + + return next(c) + } +} diff --git a/internal/common/logger_middleware.go b/internal/common/logger_middleware.go new file mode 100644 index 000000000..0a26c6e8a --- /dev/null +++ b/internal/common/logger_middleware.go @@ -0,0 +1,18 @@ +package common + +import ( + "github.com/labstack/echo/v4" + "github.com/sirupsen/logrus" +) + +// Store context in request logger to propagate correlation ids +func LoggerMiddleware(next echo.HandlerFunc) echo.HandlerFunc { + return func(c echo.Context) error { + c.SetLogger(&EchoLogrusLogger{ + Logger: logrus.StandardLogger(), + Ctx: c.Request().Context(), + }) + + return next(c) + } +} diff --git a/internal/common/operation_id.go b/internal/common/operation_id.go index 1c522e78e..2c27ade16 100644 --- a/internal/common/operation_id.go +++ b/internal/common/operation_id.go @@ -1,18 +1,29 @@ package common import ( + "context" + "github.com/labstack/echo/v4" "github.com/segmentio/ksuid" ) +type ctxKey string + const OperationIDKey string = "operationID" +const operationIDKeyCtx ctxKey = ctxKey(OperationIDKey) // Adds a time-sortable globally unique identifier to an echo.Context if not already set func OperationIDMiddleware(next echo.HandlerFunc) echo.HandlerFunc { return func(c echo.Context) error { if c.Get(OperationIDKey) == nil { - c.Set(OperationIDKey, GenerateOperationID()) + oid := GenerateOperationID() + c.Set(OperationIDKey, oid) + + ctx := c.Request().Context() + ctx = context.WithValue(ctx, operationIDKeyCtx, oid) + c.SetRequest(c.Request().WithContext(ctx)) } + return next(c) } } diff --git a/vendor/modules.txt b/vendor/modules.txt index 3b8314d9e..c77b92eb9 100644 --- a/vendor/modules.txt +++ b/vendor/modules.txt @@ -437,7 +437,7 @@ github.com/coreos/go-semver/semver ## explicit github.com/coreos/go-systemd/activation github.com/coreos/go-systemd/journal -# github.com/cyberphone/json-canonicalization v0.0.0-20231011164504-785e29786b46 +# github.com/cyberphone/json-canonicalization v0.0.0-20231217050601-ba74d44ecf5f ## explicit github.com/cyberphone/json-canonicalization/go/src/webpki.org/jsoncanonicalizer # github.com/cyphar/filepath-securejoin v0.2.4