WEB-API: Add contextual logging during the request handling

cmd/aznum2words-webapp/constant/context.go

@@ -0,0 +1,7 @@
+package constant
+
+// Common Keys used in the context
+const (
+	CtxCorrelationId = "Ctx-Correlation-Id"
+	CtxZLogger       = "Ctx-ZLogger-Component"
+)

cmd/aznum2words-webapp/constant/headers.go

@@ -0,0 +1,9 @@
+package constant
+
+import "github.com/labstack/echo/v4"
+
+// Common Headers
+const (
+	HeaderXCorrelationId = echo.HeaderXCorrelationID
+	HeaderUserAgent      = "User-Agent"
+)

cmd/aznum2words-webapp/constant/logger.go

@@ -0,0 +1,17 @@
+package constant
+
+const (
+	LogAppName   = "app"
+	LogEnvName   = "env"
+	LogGoVersion = "go-version"
+	LogProcessId = "pid"
+	LogGoArch    = "go-arch"
+
+	LogCorrelationId  = "correlation-id"
+	LogUserAgent      = "user-agent"
+	LogClientRealIp   = "client-real-ip"
+	LogRequestUri     = "request-uri"
+	LogRequestMethod  = "request-method"
+	LogResponseStatus = "response-status"
+	LogLatency        = "latency"
+)

cmd/aznum2words-webapp/logger/logging.go

@@ -1,47 +1,112 @@
 package logger
 
 import (
+	"context"
+	"fmt"
 	"github.com/egasimov/aznum2words/cmd/aznum2words-webapp/config"
 	"github.com/egasimov/aznum2words/cmd/aznum2words-webapp/constant"
-	"log"
-	"time"
-
+	"github.com/labstack/echo/v4"
 	"go.uber.org/zap"
 	"go.uber.org/zap/zapcore"
+	"log"
+	"os"
+	"runtime"
+	"runtime/debug"
+	"time"
 )
 
-var logger *zap.Logger
+var _logger *zap.Logger
 
 func init() {
-	encoderConfig := zap.NewProductionConfig()
-	encoderConfig.Level.SetLevel(zapcore.InfoLevel)
+	zapConfig := zap.NewProductionConfig()
+	zapConfig.Level.SetLevel(zapcore.DebugLevel)
 	if config.GetConfig().DeployEnv == constant.LOCAL_ENVIRONMENT {
-		encoderConfig.Level.SetLevel(zapcore.DebugLevel)
+		zapConfig.Level.SetLevel(zapcore.DebugLevel)
+	}
+
+	// create encoder config
+	encoderConfig := zap.NewProductionEncoderConfig()
+	encoderConfig.TimeKey = "timestamp"
+	encoderConfig.MessageKey = "message"
+	encoderConfig.EncodeTime = func(time time.Time, enc zapcore.PrimitiveArrayEncoder) {
+		enc.AppendString(time.Format("2006-01-02T15:04:05.999Z"))
 	}
-	encoderConfig.EncoderConfig.TimeKey = "timestamp"
-	encoderConfig.EncoderConfig.MessageKey = "message"
-	encoderConfig.EncoderConfig.EncodeTime = zapcore.TimeEncoderOfLayout(time.RFC3339Nano)
 
-	zapLogger, err := encoderConfig.Build()
+	zapConfig.EncoderConfig = encoderConfig
+
+	zapLogger, err := zapConfig.Build()
 	if err != nil {
 		log.Fatalf("fail to build log. err: %s", err)
 	}
 
-	for k, v := range GetDefaultLogEntries() {
-		zapLogger = zapLogger.
-			With(zap.Any(k, v))
+	var defaultFields []zap.Field
+	defaultLogEntries, ok := getDefaultLogEntries()
+
+	if !ok {
+		log.Fatalf("fail to build log. err: %s", err)
+	}
+
+	for k, v := range defaultLogEntries {
+		defaultFields = append(defaultFields, zap.String(k, v))
 	}
 
-	logger = zapLogger
+	_logger = zapLogger.
+		With(defaultFields...)
 }
 
 func Logger() *zap.Logger {
-	return logger
+	return _logger
 }
 
-func GetDefaultLogEntries() map[string]string {
+func getDefaultLogEntries() (map[string]string, bool) {
+	buildInfo, ok := debug.ReadBuildInfo()
+
+	if !ok {
+		return nil, false
+	}
+
 	return map[string]string{
-		"app": config.GetConfig().AppName,
-		"env": config.GetConfig().DeployEnv,
+		constant.LogAppName:   config.GetConfig().AppName,
+		constant.LogEnvName:   config.GetConfig().DeployEnv,
+		constant.LogGoVersion: buildInfo.GoVersion,
+		constant.LogProcessId: fmt.Sprintf("%d", os.Getpid()),
+		constant.LogGoArch:    runtime.GOARCH,
+	}, true
+}
+
+func FromCtx(ctx context.Context) *zap.Logger {
+	if l, ok := ctx.Value(constant.CtxZLogger).(*zap.Logger); ok {
+		l.Warn(
+			fmt.Sprintf("ZLogger found in the context, returning it to caller"),
+		)
+		return l
+	}
+	_logger.Warn(
+		fmt.Sprintf("ZLogger could NOT found in the context, returning default ZLogger"),
+	)
+	return _logger
+}
+
+func WithCtx(echoCtx echo.Context, ctx context.Context, zlogger *zap.Logger) context.Context {
+	if foundZLogger, ok := ctx.Value(constant.CtxZLogger).(*zap.Logger); ok {
+		if foundZLogger == zlogger {
+			return ctx
+		}
+	}
+
+	newZLogger := buildZLoggerFromEchoCtx(echoCtx, zlogger)
+	newCtx := context.WithValue(ctx, constant.CtxZLogger, newZLogger)
+	newCtx = context.WithValue(
+		newCtx, constant.CtxCorrelationId, echoCtx.Request().Header.Get(echo.HeaderXCorrelationID),
+	)
+	return newCtx
+}
+
+func buildZLoggerFromEchoCtx(echoCtx echo.Context, zlogger *zap.Logger) *zap.Logger {
+	fields := []zap.Field{
+		zap.String(constant.LogCorrelationId, echoCtx.Request().Header.Get(constant.HeaderXCorrelationId)),
+		zap.String(constant.LogUserAgent, echoCtx.Request().Header.Get(constant.HeaderUserAgent)),
+		// Add more key-value pairs as needed
 	}
+	return zlogger.With(fields...)
 }

cmd/aznum2words-webapp/middleware/contextFillerMiddleware.go

@@ -0,0 +1,26 @@
+package middleware
+
+import (
+	"fmt"
+	"github.com/egasimov/aznum2words/cmd/aznum2words-webapp/logger"
+	"github.com/labstack/echo/v4"
+	"go.uber.org/zap"
+)
+
+func ContextFillerMiddleware(zlog *zap.Logger) echo.MiddlewareFunc {
+	return func(next echo.HandlerFunc) echo.HandlerFunc {
+		return func(echoCtx echo.Context) error {
+			zlog.Debug(
+				fmt.Sprintf(
+					"Creating new context with ZLogger for incoming request",
+				),
+			)
+
+			req := echoCtx.Request()
+			newCtx := logger.WithCtx(echoCtx, req.Context(), logger.Logger())
+			echoCtx.SetRequest(req.Clone(newCtx))
+
+			return next(echoCtx)
+		}
+	}
+}

cmd/aznum2words-webapp/middleware/httpLoggerMiddleware.go

@@ -0,0 +1,66 @@
+package middleware
+
+import (
+	"fmt"
+	"github.com/egasimov/aznum2words/cmd/aznum2words-webapp/constant"
+	"github.com/egasimov/aznum2words/cmd/aznum2words-webapp/logger"
+	"github.com/labstack/echo/v4"
+	"go.uber.org/zap"
+	"time"
+)
+
+func HttpLoggerMiddleware() echo.MiddlewareFunc {
+	return func(next echo.HandlerFunc) echo.HandlerFunc {
+		return func(echoCtx echo.Context) error {
+			start := time.Now()
+
+			req := echoCtx.Request()
+			res := echoCtx.Response()
+
+			zlog := logger.FromCtx(req.Context())
+
+			zlog.Debug(
+				fmt.Sprintf(
+					"[Request]  | Uri: %s %s | RawQuery: %s",
+					req.Method, req.RequestURI,
+					req.URL.RawQuery,
+				),
+			)
+
+			if err := next(echoCtx); err != nil {
+				zlog.Error(
+					fmt.Sprintf("An error occurred: %v", err),
+					zap.Error(err),
+				)
+				echoCtx.Error(err)
+			}
+
+			latency := time.Since(start)
+
+			zlog.Debug(
+				fmt.Sprintf(
+					"[Response] | Uri: %s %s | Elapsed time: %s | Result: %d",
+					req.Method, req.RequestURI,
+					latency.String(),
+					res.Status,
+				),
+			)
+
+			zlog.Info(
+				fmt.Sprintf("[Request] Uri: %s %s | [Response] Status: %d Elapsed time: %s",
+					req.Method, req.RequestURI,
+					res.Status,
+					latency.String(),
+				),
+				zap.String(constant.LogRequestMethod, req.Method),
+				zap.String(constant.LogRequestUri, req.RequestURI),
+				zap.String(constant.LogUserAgent, req.UserAgent()),
+				zap.String(constant.LogClientRealIp, req.Header.Get(echo.HeaderXRealIP)),
+				zap.Int(constant.LogResponseStatus, res.Status),
+				zap.String(constant.LogLatency, latency.String()),
+			)
+
+			return nil
+		}
+	}
+}

cmd/aznum2words-webapp/router/router.go

@@ -3,24 +3,46 @@ package router
 import (
 	"fmt"
 	"github.com/egasimov/aznum2words/cmd/aznum2words-webapp/logger"
+	"github.com/egasimov/aznum2words/cmd/aznum2words-webapp/middleware"
+	"github.com/google/uuid"
 	"github.com/labstack/echo-contrib/prometheus"
 	"github.com/labstack/echo/v4"
 	echomiddleware "github.com/labstack/echo/v4/middleware"
-	"strings"
 )
 
+var _requestIDConfig = echomiddleware.RequestIDConfig{
+	TargetHeader: echo.HeaderXCorrelationID,
+	Generator: func() string {
+		return uuid.New().String()
+	},
+	RequestIDHandler: func(echoCtx echo.Context, newRequestId string) {
+		zlog := logger.FromCtx(echoCtx.Request().Context())
+
+		req := echoCtx.Request()
+		if val := req.Header.Get(echo.HeaderXCorrelationID); val == "" {
+			zlog.Info(
+				fmt.Sprintf(
+					"Correlation ID not found in the request, going to set ID %s to request",
+					newRequestId,
+				),
+			)
+			echoCtx.Request().Header.
+				Set(echo.HeaderXCorrelationID, newRequestId)
+		}
+	},
+}
+
 func NewMainServer() *echo.Echo {
 	echoMainServer := echo.New()
 	echoMainServer.HideBanner = true
 	echoMainServer.HidePort = true
 
 	echoMainServer.Use(echomiddleware.CORS())
-	echoMainServer.Use(echomiddleware.RequestIDWithConfig(
-		echomiddleware.RequestIDConfig{
-			TargetHeader: echo.HeaderXCorrelationID,
-		}))
+	echoMainServer.Use(echomiddleware.RequestIDWithConfig(_requestIDConfig))
+
 	// Log all requests
-	echoMainServer.Use(echomiddleware.LoggerWithConfig(getLoggerConfig()))
+	echoMainServer.Use(middleware.ContextFillerMiddleware(logger.Logger()))
+	echoMainServer.Use(middleware.HttpLoggerMiddleware())
 
 	return echoMainServer
 }
@@ -30,13 +52,13 @@ func NewPrometheusServer(echoMainServer *echo.Echo) *echo.Echo {
 	echoPrometheus := echo.New()
 	echoPrometheus.HideBanner = true
 	echoPrometheus.HidePort = true
+
 	echoPrometheus.Use(echomiddleware.CORS())
-	echoPrometheus.Use(echomiddleware.RequestIDWithConfig(
-		echomiddleware.RequestIDConfig{
-			TargetHeader: echo.HeaderXCorrelationID,
-		}))
+	echoPrometheus.Use(echomiddleware.RequestIDWithConfig(_requestIDConfig))
+
 	// Log all requests
-	echoPrometheus.Use(echomiddleware.LoggerWithConfig(getLoggerConfig()))
+	echoPrometheus.Use(middleware.ContextFillerMiddleware(logger.Logger()))
+	echoPrometheus.Use(middleware.HttpLoggerMiddleware())
 
 	prom := prometheus.NewPrometheus("echo", nil)
 
@@ -48,32 +70,3 @@ func NewPrometheusServer(echoMainServer *echo.Echo) *echo.Echo {
 
 	return echoPrometheus
 }
-
-func getLoggerConfig() echomiddleware.LoggerConfig {
-	return echomiddleware.LoggerConfig{
-		Format: `{"time":"${time_rfc3339_nano}","x-correlation-id":"${header:x-correlation-id}","remote_ip":"${remote_ip}",` +
-			`"host":"${host}","method":"${method}","uri":"${uri}","user_agent":"${user_agent}",` +
-			addDefaultLogEntries() +
-			`"status":${status},"error":"${error}","latency":${latency},"latency_human":"${latency_human}"}` + "\n",
-		CustomTimeFormat: "2006-01-02 15:04:05.00000",
-	}
-}
-
-func addDefaultLogEntries() string {
-	var logEntries []string
-	for k, v := range logger.GetDefaultLogEntries() {
-		logEntries = append(logEntries, addKeyValPair(k, v, true))
-	}
-
-	return strings.Join(logEntries, "")
-}
-
-func addKeyValPair(keyName string, valName string, appendComma bool) string {
-	var result string
-	if appendComma {
-		result = fmt.Sprintf(`"%s":"%s",`, keyName, valName)
-	} else {
-		result = fmt.Sprintf(`"%s":"%s"`, keyName, valName)
-	}
-	return result
-}