[#148] Add trace_id to logs

Signed-off-by: Roman Loginov <r.loginov@yadro.com>
2024-10-08 12:08:39 +03:00 · 2024-10-08 12:08:39 +03:00 · fc86ab3511
commit fc86ab3511
parent 495f745535
7 changed files with 104 additions and 48 deletions
--- a/CHANGELOG.md
+++ b/CHANGELOG.md
@ -3,7 +3,10 @@
 This document outlines major changes between releases.

 ## [Unreleased]
+
+### Added
 - Support percent-encoding for GET queries (#134)
+- Add `trace_id` to logs (#148)

 ### Changed
 - Update go version to 1.22 (#132)
--- a/cmd/http-gw/app.go
+++ b/cmd/http-gw/app.go
@ -42,6 +42,7 @@ import (
 	"github.com/nspcc-dev/neo-go/pkg/wallet"
 	"github.com/spf13/viper"
 	"github.com/valyala/fasthttp"
+	"go.opentelemetry.io/otel/trace"
 	"go.uber.org/zap"
 	"golang.org/x/exp/slices"
 )
@ -589,15 +590,15 @@ func (a *app) configureRouter(handler *handler.Handler) {
 		response.Error(r, "Method Not Allowed", fasthttp.StatusMethodNotAllowed)
 	}

-	r.POST("/upload/{cid}", a.logger(a.canonicalizer(a.tokenizer(a.tracer(a.reqNamespace(handler.Upload))))))
+	r.POST("/upload/{cid}", a.tracer(a.logger(a.canonicalizer(a.tokenizer(a.reqNamespace(handler.Upload))))))
 	a.log.Info(logs.AddedPathUploadCid)
-	r.GET("/get/{cid}/{oid:*}", a.logger(a.canonicalizer(a.tokenizer(a.tracer(a.reqNamespace(handler.DownloadByAddressOrBucketName))))))
-	r.HEAD("/get/{cid}/{oid:*}", a.logger(a.canonicalizer(a.tokenizer(a.tracer(a.reqNamespace(handler.HeadByAddressOrBucketName))))))
+	r.GET("/get/{cid}/{oid:*}", a.tracer(a.logger(a.canonicalizer(a.tokenizer(a.reqNamespace(handler.DownloadByAddressOrBucketName))))))
+	r.HEAD("/get/{cid}/{oid:*}", a.tracer(a.logger(a.canonicalizer(a.tokenizer(a.reqNamespace(handler.HeadByAddressOrBucketName))))))
 	a.log.Info(logs.AddedPathGetCidOid)
-	r.GET("/get_by_attribute/{cid}/{attr_key}/{attr_val:*}", a.logger(a.canonicalizer(a.tokenizer(a.tracer(a.reqNamespace(handler.DownloadByAttribute))))))
-	r.HEAD("/get_by_attribute/{cid}/{attr_key}/{attr_val:*}", a.logger(a.canonicalizer(a.tokenizer(a.tracer(a.reqNamespace(handler.HeadByAttribute))))))
+	r.GET("/get_by_attribute/{cid}/{attr_key}/{attr_val:*}", a.tracer(a.logger(a.canonicalizer(a.tokenizer(a.reqNamespace(handler.DownloadByAttribute))))))
+	r.HEAD("/get_by_attribute/{cid}/{attr_key}/{attr_val:*}", a.tracer(a.logger(a.canonicalizer(a.tokenizer(a.reqNamespace(handler.HeadByAttribute))))))
 	a.log.Info(logs.AddedPathGetByAttributeCidAttrKeyAttrVal)
-	r.GET("/zip/{cid}/{prefix:*}", a.logger(a.canonicalizer(a.tokenizer(a.tracer(a.reqNamespace(handler.DownloadZipped))))))
+	r.GET("/zip/{cid}/{prefix:*}", a.tracer(a.logger(a.canonicalizer(a.tokenizer(a.reqNamespace(handler.DownloadZipped))))))
 	a.log.Info(logs.AddedPathZipCidPrefix)

 	a.webServer.Handler = r.Handler
@ -605,11 +606,24 @@ func (a *app) configureRouter(handler *handler.Handler) {

 func (a *app) logger(h fasthttp.RequestHandler) fasthttp.RequestHandler {
 	return func(req *fasthttp.RequestCtx) {
-		a.log.Info(logs.Request, zap.String("remote", req.RemoteAddr().String()),
+		requiredFields := []zap.Field{zap.Uint64("id", req.ID())}
+		reqCtx := utils.GetContextFromRequest(req)
+		if traceID := trace.SpanFromContext(reqCtx).SpanContext().TraceID(); traceID.IsValid() {
+			requiredFields = append(requiredFields, zap.String("trace_id", traceID.String()))
+		}
+		log := a.log.With(requiredFields...)
+
+		reqCtx = utils.SetReqLog(reqCtx, log)
+		utils.SetContextToRequest(reqCtx, req)
+
+		fields := []zap.Field{
+			zap.String("remote", req.RemoteAddr().String()),
 			zap.ByteString("method", req.Method()),
 			zap.ByteString("path", req.Path()),
 			zap.ByteString("query", req.QueryArgs().QueryString()),
-			zap.Uint64("id", req.ID()))
+		}
+
+		log.Info(logs.Request, fields...)
 		h(req)
 	}
 }
@ -648,9 +662,12 @@ func (a *app) canonicalizer(h fasthttp.RequestHandler) fasthttp.RequestHandler {

 func (a *app) tokenizer(h fasthttp.RequestHandler) fasthttp.RequestHandler {
 	return func(req *fasthttp.RequestCtx) {
-		appCtx, err := tokens.StoreBearerTokenAppCtx(a.ctx, req)
+		reqCtx := utils.GetContextFromRequest(req)
+		appCtx, err := tokens.StoreBearerTokenAppCtx(reqCtx, req)
 		if err != nil {
-			a.log.Error(logs.CouldNotFetchAndStoreBearerToken, zap.Uint64("id", req.ID()), zap.Error(err))
+			log := utils.GetReqLogOrDefault(reqCtx, a.log)
+
+			log.Error(logs.CouldNotFetchAndStoreBearerToken, zap.Error(err))
 			response.Error(req, "could not fetch and store bearer token: "+err.Error(), fasthttp.StatusBadRequest)
 			return
 		}
@ -661,9 +678,7 @@ func (a *app) tokenizer(h fasthttp.RequestHandler) fasthttp.RequestHandler {

 func (a *app) tracer(h fasthttp.RequestHandler) fasthttp.RequestHandler {
 	return func(req *fasthttp.RequestCtx) {
-		appCtx := utils.GetContextFromRequest(req)
-
-		appCtx, span := utils.StartHTTPServerSpan(appCtx, req, "REQUEST")
+		appCtx, span := utils.StartHTTPServerSpan(a.ctx, req, "REQUEST")
 		defer func() {
 			utils.SetHTTPTraceInfo(appCtx, span, req)
 			span.End()
--- a/internal/handler/browse.go
+++ b/internal/handler/browse.go
@ -113,8 +113,10 @@ func urlencode(prefix, filename string) string {
 }

 func (h *Handler) browseObjects(c *fasthttp.RequestCtx, bucketInfo *data.BucketInfo, prefix string) {
-	log := h.log.With(zap.String("bucket", bucketInfo.Name))
 	ctx := utils.GetContextFromRequest(c)
+	reqLog := utils.GetReqLogOrDefault(ctx, h.log)
+	log := reqLog.With(zap.String("bucket", bucketInfo.Name))
+
 	nodes, err := h.listObjects(ctx, bucketInfo, prefix)
 	if err != nil {
 		logAndSendBucketError(c, log, err)
--- a/internal/handler/download.go
+++ b/internal/handler/download.go
@ -84,16 +84,17 @@ func (h *Handler) DownloadZipped(c *fasthttp.RequestCtx) {
 	scid, _ := c.UserValue("cid").(string)
 	prefix, _ := c.UserValue("prefix").(string)

+	ctx := utils.GetContextFromRequest(c)
+	log := utils.GetReqLogOrDefault(ctx, h.log)
+
 	prefix, err := url.QueryUnescape(prefix)
 	if err != nil {
-		h.log.Error(logs.FailedToUnescapeQuery, zap.String("cid", scid), zap.String("prefix", prefix), zap.Uint64("id", c.ID()), zap.Error(err))
+		log.Error(logs.FailedToUnescapeQuery, zap.String("cid", scid), zap.String("prefix", prefix), zap.Error(err))
 		response.Error(c, "could not unescape prefix: "+err.Error(), fasthttp.StatusBadRequest)
 		return
 	}

-	log := h.log.With(zap.String("cid", scid), zap.String("prefix", prefix), zap.Uint64("id", c.ID()))
-
-	ctx := utils.GetContextFromRequest(c)
+	log = log.With(zap.String("cid", scid), zap.String("prefix", prefix))

 	bktInfo, err := h.getBucketInfo(ctx, scid, log)
 	if err != nil {
--- a/internal/handler/handler.go
+++ b/internal/handler/handler.go
@ -190,13 +190,12 @@ func New(params *AppParams, config Config, tree *tree.Tree) *Handler {
 // byAddress is a wrapper for function (e.g. request.headObject, request.receiveFile) that
 // prepares request and object address to it.
 func (h *Handler) byAddress(c *fasthttp.RequestCtx, f func(context.Context, request, oid.Address)) {
-	var (
-		idCnr, _ = c.UserValue("cid").(string)
-		idObj, _ = c.UserValue("oid").(string)
-		log      = h.log.With(zap.String("cid", idCnr), zap.String("oid", idObj))
-	)
+	idCnr, _ := c.UserValue("cid").(string)
+	idObj, _ := c.UserValue("oid").(string)

 	ctx := utils.GetContextFromRequest(c)
+	reqLog := utils.GetReqLogOrDefault(ctx, h.log)
+	log := reqLog.With(zap.String("cid", idCnr), zap.String("oid", idObj))

 	bktInfo, err := h.getBucketInfo(ctx, idCnr, log)
 	if err != nil {
@ -219,12 +218,13 @@ func (h *Handler) byAddress(c *fasthttp.RequestCtx, f func(context.Context, requ
 // byObjectName is a wrapper for function (e.g. request.headObject, request.receiveFile) that
 // prepares request and object address to it.
 func (h *Handler) byObjectName(c *fasthttp.RequestCtx, f func(context.Context, request, oid.Address)) {
-	var (
-		bucketname = c.UserValue("cid").(string)
-		key        = c.UserValue("oid").(string)
-		log        = h.log.With(zap.String("bucketname", bucketname), zap.String("key", key))
-		download   = c.QueryArgs().GetBool("download")
-	)
+	bucketname := c.UserValue("cid").(string)
+	key := c.UserValue("oid").(string)
+	download := c.QueryArgs().GetBool("download")
+
+	ctx := utils.GetContextFromRequest(c)
+	reqLog := utils.GetReqLogOrDefault(ctx, h.log)
+	log := reqLog.With(zap.String("bucketname", bucketname), zap.String("key", key))

 	unescapedKey, err := url.QueryUnescape(key)
 	if err != nil {
@ -232,8 +232,6 @@ func (h *Handler) byObjectName(c *fasthttp.RequestCtx, f func(context.Context, r
 		return
 	}

-	ctx := utils.GetContextFromRequest(c)
-
 	bktInfo, err := h.getBucketInfo(ctx, bucketname, log)
 	if err != nil {
 		logAndSendBucketError(c, log, err)
@ -275,23 +273,24 @@ func (h *Handler) byAttribute(c *fasthttp.RequestCtx, f func(context.Context, re
 	key, _ := c.UserValue("attr_key").(string)
 	val, _ := c.UserValue("attr_val").(string)

+	ctx := utils.GetContextFromRequest(c)
+	log := utils.GetReqLogOrDefault(ctx, h.log)
+
 	key, err := url.QueryUnescape(key)
 	if err != nil {
-		h.log.Error(logs.FailedToUnescapeQuery, zap.String("cid", scid), zap.String("attr_key", key), zap.Uint64("id", c.ID()), zap.Error(err))
+		log.Error(logs.FailedToUnescapeQuery, zap.String("cid", scid), zap.String("attr_key", key), zap.Error(err))
 		response.Error(c, "could not unescape attr_key: "+err.Error(), fasthttp.StatusBadRequest)
 		return
 	}

 	val, err = url.QueryUnescape(val)
 	if err != nil {
-		h.log.Error(logs.FailedToUnescapeQuery, zap.String("cid", scid), zap.String("attr_val", val), zap.Uint64("id", c.ID()), zap.Error(err))
+		log.Error(logs.FailedToUnescapeQuery, zap.String("cid", scid), zap.String("attr_val", val), zap.Error(err))
 		response.Error(c, "could not unescape attr_val: "+err.Error(), fasthttp.StatusBadRequest)
 		return
 	}

-	log := h.log.With(zap.String("cid", scid), zap.String("attr_key", key), zap.String("attr_val", val))
-
-	ctx := utils.GetContextFromRequest(c)
+	log = log.With(zap.String("cid", scid), zap.String("attr_key", key), zap.String("attr_val", val))

 	bktInfo, err := h.getBucketInfo(ctx, scid, log)
 	if err != nil {
--- a/internal/handler/upload.go
+++ b/internal/handler/upload.go
@ -45,16 +45,18 @@ func (pr *putResponse) encode(w io.Writer) error {
 // Upload handles multipart upload request.
 func (h *Handler) Upload(c *fasthttp.RequestCtx) {
 	var (
-		file       MultipartFile
-		idObj      oid.ID
-		addr       oid.Address
-		scid, _    = c.UserValue("cid").(string)
-		log        = h.log.With(zap.String("cid", scid))
-		bodyStream = c.RequestBodyStream()
-		drainBuf   = make([]byte, drainBufSize)
+		file  MultipartFile
+		idObj oid.ID
+		addr  oid.Address
 	)

+	scid, _ := c.UserValue("cid").(string)
+	bodyStream := c.RequestBodyStream()
+	drainBuf := make([]byte, drainBufSize)
+
 	ctx := utils.GetContextFromRequest(c)
+	reqLog := utils.GetReqLogOrDefault(ctx, h.log)
+	log := reqLog.With(zap.String("cid", scid))

 	bktInfo, err := h.getBucketInfo(ctx, scid, log)
 	if err != nil {
@ -75,13 +77,15 @@ func (h *Handler) Upload(c *fasthttp.RequestCtx) {
 			zap.Error(err),
 		)
 	}()
+
 	boundary := string(c.Request.Header.MultipartFormBoundary())
-	if file, err = fetchMultipartFile(h.log, bodyStream, boundary); err != nil {
+	if file, err = fetchMultipartFile(log, bodyStream, boundary); err != nil {
 		log.Error(logs.CouldNotReceiveMultipartForm, zap.Error(err))
 		response.Error(c, "could not receive multipart/form: "+err.Error(), fasthttp.StatusBadRequest)
 		return
 	}
-	filtered, err := filterHeaders(h.log, &c.Request.Header)
+
+	filtered, err := filterHeaders(log, &c.Request.Header)
 	if err != nil {
 		log.Error(logs.CouldNotProcessHeaders, zap.Error(err))
 		response.Error(c, err.Error(), fasthttp.StatusBadRequest)
@ -143,7 +147,7 @@ func (h *Handler) Upload(c *fasthttp.RequestCtx) {
 	}

 	if idObj, err = h.frostfs.CreateObject(ctx, prm); err != nil {
-		h.handlePutFrostFSErr(c, err)
+		h.handlePutFrostFSErr(c, err, log)
 		return
 	}

@ -174,11 +178,11 @@ func (h *Handler) Upload(c *fasthttp.RequestCtx) {
 	c.Response.Header.SetContentType(jsonHeader)
 }

-func (h *Handler) handlePutFrostFSErr(r *fasthttp.RequestCtx, err error) {
+func (h *Handler) handlePutFrostFSErr(r *fasthttp.RequestCtx, err error, log *zap.Logger) {
 	statusCode, msg, additionalFields := response.FormErrorResponse("could not store file in frostfs", err)
 	logFields := append([]zap.Field{zap.Error(err)}, additionalFields...)

-	h.log.Error(logs.CouldNotStoreFileInFrostfs, logFields...)
+	log.Error(logs.CouldNotStoreFileInFrostfs, logFields...)
 	response.Error(r, msg, statusCode)
 }

--- a/utils/util.go
+++ b/utils/util.go
@ -4,6 +4,7 @@ import (
 	"context"

 	"github.com/valyala/fasthttp"
+	"go.uber.org/zap"
 )

 // SetContextToRequest adds new context to fasthttp request.
@ -15,3 +16,34 @@ func SetContextToRequest(ctx context.Context, c *fasthttp.RequestCtx) {
 func GetContextFromRequest(c *fasthttp.RequestCtx) context.Context {
 	return c.UserValue("context").(context.Context)
 }
+
+type ctxReqLoggerKeyType struct{}
+
+// SetReqLog sets child zap.Logger in the context.
+func SetReqLog(ctx context.Context, log *zap.Logger) context.Context {
+	if ctx == nil {
+		return nil
+	}
+	return context.WithValue(ctx, ctxReqLoggerKeyType{}, log)
+}
+
+// GetReqLog returns log if set.
+// If zap.Logger isn't set returns nil.
+func GetReqLog(ctx context.Context) *zap.Logger {
+	if ctx == nil {
+		return nil
+	} else if r, ok := ctx.Value(ctxReqLoggerKeyType{}).(*zap.Logger); ok {
+		return r
+	}
+	return nil
+}
+
+// GetReqLogOrDefault returns log from context, if it exists.
+// If the log is missing from the context, the default logger is returned.
+func GetReqLogOrDefault(ctx context.Context, defaultLog *zap.Logger) *zap.Logger {
+	log := GetReqLog(ctx)
+	if log == nil {
+		log = defaultLog
+	}
+	return log
+}