From 64f0e2f636cbb77bfe125d9529c12aa323321089 Mon Sep 17 00:00:00 2001 From: Yunkon Kim Date: Wed, 11 Sep 2024 22:55:50 +0900 Subject: [PATCH] Add middleware to support tracing-like functionalities * Add TracingHook to logger for logging ctx * Add traceLogger * Add tracing middleware * Support a logger to be used in tracing middleware - Log to file, Loglevel=trace * Update API docs * Split the existing middlewares into individual files - It could be helpful to clearly show callers in logs * Increase default LOGFILE_MAXSIZE 1000 MB --- Dockerfile | 2 +- .../middlewares/requestIdAndDetailsIssuer.go | 46 ++++++++ ...stom-middleware.go => responseBodyDump.go} | 107 ------------------ src/api/rest/server/middlewares/tracing.go | 70 ++++++++++++ src/api/rest/server/middlewares/zerologger.go | 77 +++++++++++++ src/api/rest/server/server.go | 5 +- src/core/common/logger/logger.go | 40 ++++++- 7 files changed, 237 insertions(+), 110 deletions(-) create mode 100644 src/api/rest/server/middlewares/requestIdAndDetailsIssuer.go rename src/api/rest/server/middlewares/{custom-middleware/custom-middleware.go => responseBodyDump.go} (57%) create mode 100644 src/api/rest/server/middlewares/tracing.go create mode 100644 src/api/rest/server/middlewares/zerologger.go diff --git a/Dockerfile b/Dockerfile index 2347b4197..da5db3013 100644 --- a/Dockerfile +++ b/Dockerfile @@ -70,7 +70,7 @@ ENV TB_ROOT_PATH=/app \ TB_DEFAULT_NAMESPACE=default \ TB_DEFAULT_CREDENTIALHOLDER=admin \ TB_LOGFILE_PATH=/app/log/tumblebug.log \ - TB_LOGFILE_MAXSIZE=10 \ + TB_LOGFILE_MAXSIZE=1000 \ TB_LOGFILE_MAXBACKUPS=3 \ TB_LOGFILE_MAXAGE=30 \ TB_LOGFILE_COMPRESS=false \ diff --git a/src/api/rest/server/middlewares/requestIdAndDetailsIssuer.go b/src/api/rest/server/middlewares/requestIdAndDetailsIssuer.go new file mode 100644 index 000000000..14df1c42b --- /dev/null +++ b/src/api/rest/server/middlewares/requestIdAndDetailsIssuer.go @@ -0,0 +1,46 @@ +package middlewares + +import ( + "fmt" + "time" + + "github.com/cloud-barista/cb-tumblebug/src/core/common" + "github.com/labstack/echo/v4" +) + +func RequestIdAndDetailsIssuer(next echo.HandlerFunc) echo.HandlerFunc { + return func(c echo.Context) error { + // log.Debug().Msg("Start - Request ID middleware") + + // Make X-Request-Id visible to all handlers + c.Response().Header().Set("Access-Control-Expose-Headers", echo.HeaderXRequestID) + + // Get or generate Request ID + reqID := c.Request().Header.Get(echo.HeaderXRequestID) + if reqID == "" { + reqID = fmt.Sprintf("%d", time.Now().UnixNano()) + } + + // Set Request on the context + c.Set("RequestID", reqID) + + //log.Trace().Msgf("(Request ID middleware) Request ID: %s", reqID) + if _, ok := common.RequestMap.Load(reqID); ok { + return fmt.Errorf("the X-Request-Id is already in use") + } + + // Set "X-Request-Id" in response header + c.Response().Header().Set(echo.HeaderXRequestID, reqID) + + details := common.RequestDetails{ + StartTime: time.Now(), + Status: "Handling", + RequestInfo: common.ExtractRequestInfo(c.Request()), + } + common.RequestMap.Store(reqID, details) + + // log.Debug().Msg("End - Request ID middleware") + + return next(c) + } +} diff --git a/src/api/rest/server/middlewares/custom-middleware/custom-middleware.go b/src/api/rest/server/middlewares/responseBodyDump.go similarity index 57% rename from src/api/rest/server/middlewares/custom-middleware/custom-middleware.go rename to src/api/rest/server/middlewares/responseBodyDump.go index d92fd19d1..2eedca5b5 100644 --- a/src/api/rest/server/middlewares/custom-middleware/custom-middleware.go +++ b/src/api/rest/server/middlewares/responseBodyDump.go @@ -3,121 +3,14 @@ package middlewares import ( "bytes" "encoding/json" - "fmt" - "strings" "time" "github.com/cloud-barista/cb-tumblebug/src/core/common" "github.com/labstack/echo/v4" "github.com/labstack/echo/v4/middleware" - "github.com/rs/zerolog/log" ) -func Zerologger(skipPatterns [][]string) echo.MiddlewareFunc { - return middleware.RequestLoggerWithConfig(middleware.RequestLoggerConfig{ - Skipper: func(c echo.Context) bool { - path := c.Request().URL.Path - query := c.Request().URL.RawQuery - for _, patterns := range skipPatterns { - isAllMatched := true - for _, pattern := range patterns { - if !strings.Contains(path+query, pattern) { - isAllMatched = false - break - } - } - if isAllMatched { - return true - } - } - return false - }, - LogError: true, - LogRequestID: true, - LogRemoteIP: true, - LogHost: true, - LogMethod: true, - LogURI: true, - LogUserAgent: false, - LogStatus: true, - LogLatency: true, - LogContentLength: true, - LogResponseSize: true, - // HandleError: true, // forwards error to the global error handler, so it can decide appropriate status code - LogValuesFunc: func(c echo.Context, v middleware.RequestLoggerValues) error { - if v.Error == nil { - log.Info(). - Str("id", v.RequestID). - Str("client_ip", v.RemoteIP). - //Str("host", v.Host). - Str("method", v.Method). - Str("URI", v.URI). - //Str("user_agent", v.UserAgent). - Int("status", v.Status). - //Int64("latency", v.Latency.Nanoseconds()). - Str("latency_human", v.Latency.String()). - Str("bytes_in", v.ContentLength). - Int64("bytes_out", v.ResponseSize). - Msg("request") - } else { - log.Error(). - Err(v.Error). - Str("id", v.RequestID). - Str("client_ip", v.RemoteIP). - // Str("host", v.Host). - Str("method", v.Method). - Str("URI", v.URI). - //Str("user_agent", v.UserAgent). - Int("status", v.Status). - // Int64("latency", v.Latency.Nanoseconds()). - Str("latency_human", v.Latency.String()). - Str("bytes_in", v.ContentLength). - Int64("bytes_out", v.ResponseSize). - Msg("request error") - } - return nil - }, - }) -} - -func RequestIdAndDetailsIssuer(next echo.HandlerFunc) echo.HandlerFunc { - return func(c echo.Context) error { - // log.Debug().Msg("Start - Request ID middleware") - - // Make X-Request-Id visible to all handlers - c.Response().Header().Set("Access-Control-Expose-Headers", echo.HeaderXRequestID) - - // Get or generate Request ID - reqID := c.Request().Header.Get(echo.HeaderXRequestID) - if reqID == "" { - reqID = fmt.Sprintf("%d", time.Now().UnixNano()) - } - - // Set Request on the context - c.Set("RequestID", reqID) - - //log.Trace().Msgf("(Request ID middleware) Request ID: %s", reqID) - if _, ok := common.RequestMap.Load(reqID); ok { - return fmt.Errorf("the X-Request-Id is already in use") - } - - // Set "X-Request-Id" in response header - c.Response().Header().Set(echo.HeaderXRequestID, reqID) - - details := common.RequestDetails{ - StartTime: time.Now(), - Status: "Handling", - RequestInfo: common.ExtractRequestInfo(c.Request()), - } - common.RequestMap.Store(reqID, details) - - // log.Debug().Msg("End - Request ID middleware") - - return next(c) - } -} - func ResponseBodyDump() echo.MiddlewareFunc { return middleware.BodyDumpWithConfig(middleware.BodyDumpConfig{ Skipper: func(c echo.Context) bool { diff --git a/src/api/rest/server/middlewares/tracing.go b/src/api/rest/server/middlewares/tracing.go new file mode 100644 index 000000000..cfbb81d08 --- /dev/null +++ b/src/api/rest/server/middlewares/tracing.go @@ -0,0 +1,70 @@ +package middlewares + +import ( + "context" + "fmt" + "time" + + "github.com/cloud-barista/cb-tumblebug/src/core/common/logger" + "github.com/labstack/echo/v4" + "github.com/rs/zerolog/log" + // "go.opentelemetry.io/otel" +) + +// Define Tracing middleware +func TracingMiddleware(next echo.HandlerFunc) echo.HandlerFunc { + return func(c echo.Context) error { + + // TODO: Be able to use this code when OpenTelemetry is integrated + // Start a new tracing context + // tracer := otel.Tracer("example-tracer") + // ctx, span := tracer.Start(c.Request().Context(), c.Path()) + // defer span.End() + + // Store trace and span IDs in the context + // traceId := span.SpanContext().TraceID().String() + // spanId := span.SpanContext().SpanID().String() + + // Get the context + ctx := c.Request().Context() + + // [NOTE] + // For now, we will use the request ID as the trace ID + // and generate a new span ID for each request + traceId := c.Response().Header().Get(echo.HeaderXRequestID) + spanId := fmt.Sprintf("%d", time.Now().UnixNano()) + + ctx = context.WithValue(ctx, logger.TraceIdKey, traceId) + ctx = context.WithValue(ctx, logger.SpanIdKey, spanId) + + // Create a childLogger with trace_id and span_id and store it in the context + childLogger := log.With().Str(string(logger.TraceIdKey), traceId).Str(string(logger.SpanIdKey), spanId).Logger() + ctx = childLogger.WithContext(ctx) + + // Set the context in the request + c.SetRequest(c.Request().WithContext(ctx)) + + // [Tracing log] when the request is received + traceLogger := logger.GetTraceLogger() + + traceLogger.Trace(). + Str(string(logger.TraceIdKey), traceId). + Str(string(logger.SpanIdKey), spanId). + Str("URI", c.Request().RequestURI). + Msg("[tracing] receive request") + + // [Tracing log] before the response is sent + // Hooks: Before Response + c.Response().Before(func() { + // Log the request details + traceLogger.Trace(). + Str(string(logger.TraceIdKey), traceId). + Str(string(logger.SpanIdKey), spanId). + Str("URI", c.Request().RequestURI). + Msg("[tracing] send response") + }) + + // Call the next handler + return next(c) + } +} diff --git a/src/api/rest/server/middlewares/zerologger.go b/src/api/rest/server/middlewares/zerologger.go new file mode 100644 index 000000000..1f5e95490 --- /dev/null +++ b/src/api/rest/server/middlewares/zerologger.go @@ -0,0 +1,77 @@ +package middlewares + +import ( + "strings" + + "github.com/labstack/echo/v4" + "github.com/labstack/echo/v4/middleware" + + "github.com/rs/zerolog/log" +) + +func Zerologger(skipPatterns [][]string) echo.MiddlewareFunc { + return middleware.RequestLoggerWithConfig(middleware.RequestLoggerConfig{ + Skipper: func(c echo.Context) bool { + path := c.Request().URL.Path + query := c.Request().URL.RawQuery + for _, patterns := range skipPatterns { + isAllMatched := true + for _, pattern := range patterns { + if !strings.Contains(path+query, pattern) { + isAllMatched = false + break + } + } + if isAllMatched { + return true + } + } + return false + }, + LogError: true, + LogRequestID: true, + LogRemoteIP: true, + LogHost: true, + LogMethod: true, + LogURI: true, + LogUserAgent: false, + LogStatus: true, + LogLatency: true, + LogContentLength: true, + LogResponseSize: true, + // HandleError: true, // forwards error to the global error handler, so it can decide appropriate status code + LogValuesFunc: func(c echo.Context, v middleware.RequestLoggerValues) error { + if v.Error == nil { + log.Info(). + Str("id", v.RequestID). + Str("client_ip", v.RemoteIP). + //Str("host", v.Host). + Str("method", v.Method). + Str("URI", v.URI). + //Str("user_agent", v.UserAgent). + Int("status", v.Status). + //Int64("latency", v.Latency.Nanoseconds()). + Str("latency_human", v.Latency.String()). + Str("bytes_in", v.ContentLength). + Int64("bytes_out", v.ResponseSize). + Msg("request") + } else { + log.Error(). + Err(v.Error). + Str("id", v.RequestID). + Str("client_ip", v.RemoteIP). + // Str("host", v.Host). + Str("method", v.Method). + Str("URI", v.URI). + //Str("user_agent", v.UserAgent). + Int("status", v.Status). + // Int64("latency", v.Latency.Nanoseconds()). + Str("latency_human", v.Latency.String()). + Str("bytes_in", v.ContentLength). + Int64("bytes_out", v.ResponseSize). + Msg("request error") + } + return nil + }, + }) +} diff --git a/src/api/rest/server/server.go b/src/api/rest/server/server.go index a49a80a5d..56973c26e 100644 --- a/src/api/rest/server/server.go +++ b/src/api/rest/server/server.go @@ -33,8 +33,8 @@ import ( rest_common "github.com/cloud-barista/cb-tumblebug/src/api/rest/server/common" rest_label "github.com/cloud-barista/cb-tumblebug/src/api/rest/server/common/label" rest_infra "github.com/cloud-barista/cb-tumblebug/src/api/rest/server/infra" + "github.com/cloud-barista/cb-tumblebug/src/api/rest/server/middlewares" "github.com/cloud-barista/cb-tumblebug/src/api/rest/server/middlewares/authmw" - middlewares "github.com/cloud-barista/cb-tumblebug/src/api/rest/server/middlewares/custom-middleware" rest_resource "github.com/cloud-barista/cb-tumblebug/src/api/rest/server/resource" rest_netutil "github.com/cloud-barista/cb-tumblebug/src/api/rest/server/util" @@ -109,6 +109,9 @@ func RunServer(port string) { // Custom middleware for RequestID and RequestDetails e.Use(middlewares.RequestIdAndDetailsIssuer) + // Custom middleware for tracing + e.Use(middlewares.TracingMiddleware) + // Custom middleware for ResponseBodyDump e.Use(middlewares.ResponseBodyDump()) diff --git a/src/core/common/logger/logger.go b/src/core/common/logger/logger.go index 9fb14687c..193de07ef 100644 --- a/src/core/common/logger/logger.go +++ b/src/core/common/logger/logger.go @@ -12,9 +12,35 @@ import ( "gopkg.in/natefinch/lumberjack.v2" ) +// Define context keys +type contextKey string + +const ( + TraceIdKey contextKey = "traceId" + SpanIdKey contextKey = "spanId" +) + +// Define TracingHook struct +type TracingHook struct{} + +// Run method: Executed when a log event occurs +func (h TracingHook) Run(e *zerolog.Event, level zerolog.Level, msg string) { + ctx := e.GetCtx() + traceID := ctx.Value(TraceIdKey) + spanID := ctx.Value(SpanIdKey) + + if traceID != nil { + e.Str(string(TraceIdKey), traceID.(string)) + } + if spanID != nil { + e.Str(string(SpanIdKey), spanID.(string)) + } +} + var ( sharedLogFile *lumberjack.Logger once sync.Once + traceLogger zerolog.Logger ) type Config struct { @@ -57,7 +83,7 @@ func NewLogger(config Config) *zerolog.Logger { config.LogFilePath = "./log/app.log" } if config.MaxSize == 0 { - config.MaxSize = 100 // in MB + config.MaxSize = 1000 // in MB } if config.MaxBackups == 0 { config.MaxBackups = 3 @@ -90,11 +116,18 @@ func NewLogger(config Config) *zerolog.Logger { if err := os.Chmod(config.LogFilePath, 0644); err != nil { log.Fatal().Msgf("Failed to change file permissions: %v", err) } + + // traceLogger = zerolog.New(sharedLogFile).Level(zerolog.TraceLevel).With().Timestamp().Caller().Logger() + traceLogger = zerolog.New(sharedLogFile).Level(zerolog.TraceLevel).With().Timestamp().Logger() + traceLogger.Hook(TracingHook{}) }) level := getLogLevel(config.LogLevel) logger := configureWriter(config.LogWriter, level) + // Add tracing hook to the logger + logger.Hook(TracingHook{}) + // Log a message to confirm logger setup logger.Info(). Str("logLevel", level.String()). @@ -103,6 +136,11 @@ func NewLogger(config Config) *zerolog.Logger { return logger } +// GetTraceLogger returns the trace logger +func GetTraceLogger() *zerolog.Logger { + return &traceLogger +} + // getLogLevel returns the zerolog.Level based on the string level func getLogLevel(logLevel string) zerolog.Level { switch logLevel {