cloudapi: propagate operation/external id

Signed-off-by: Lukas Zapletal <lzap+git@redhat.com>

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)

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 {

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
+}

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)
 }

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)
+	}
+}

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)
+	}
+}

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)
 	}
 }