[#148] Add trace_id to logs

Signed-off-by: Roman Loginov <r.loginov@yadro.com>

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 (#152)
 
 ### Changed
 - Update go version to 1.22 (#132)

cmd/http-gw/app.go

@@ -590,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.GET("/get/{cid}/{oid:*}", a.tracer(a.logger(a.canonicalizer(a.tokenizer(a.reqNamespace(handler.DownloadByAddressOrBucketName))))))
-	r.HEAD("/get/{cid}/{oid:*}", a.logger(a.canonicalizer(a.tokenizer(a.tracer(a.reqNamespace(handler.HeadByAddressOrBucketName))))))
+	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.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.logger(a.canonicalizer(a.tokenizer(a.tracer(a.reqNamespace(handler.HeadByAttribute))))))
+	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
@@ -606,11 +606,18 @@ 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()),
+		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()))
+			zap.Uint64("id", req.ID()),
+		}
+
+		appCtx := utils.GetContextFromRequest(req)
+		log := utils.WithRequestTracing(appCtx, a.log)
+
+		log.Info(logs.Request, fields...)
 		h(req)
 	}
 }
@@ -649,9 +656,17 @@ 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)
+		appCtx, err := tokens.StoreBearerTokenAppCtx(utils.GetContextFromRequest(req), req)
 		if err != nil {
-			a.log.Error(logs.CouldNotFetchAndStoreBearerToken, zap.Uint64("id", req.ID()), zap.Error(err))
+			fields := []zap.Field{
+				zap.Uint64("id", req.ID()),
+				zap.Error(err),
+			}
+
+			reqCtx := utils.GetContextFromRequest(req)
+			log := utils.WithRequestTracing(reqCtx, a.log)
+
+			log.Error(logs.CouldNotFetchAndStoreBearerToken, fields...)
 			response.Error(req, "could not fetch and store bearer token: "+err.Error(), fasthttp.StatusBadRequest)
 			return
 		}
@@ -662,9 +677,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(a.ctx, req, "REQUEST")
-
-		appCtx, span := utils.StartHTTPServerSpan(appCtx, req, "REQUEST")
 		defer func() {
 			utils.SetHTTPTraceInfo(appCtx, span, req)
 			span.End()

internal/handler/browse.go

@@ -113,8 +113,9 @@ 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)
+	log := utils.WithRequestTracing(ctx, h.log.With(zap.String("bucket", bucketInfo.Name)))
+
 	nodes, err := h.listObjects(ctx, bucketInfo, prefix)
 	if err != nil {
 		logAndSendBucketError(c, log, err)

internal/handler/download.go

@@ -81,19 +81,21 @@ func (h *Handler) addObjectToZip(zw *zip.Writer, obj *object.Object) (io.Writer,
 
 // DownloadZipped handles zip by prefix requests.
 func (h *Handler) DownloadZipped(c *fasthttp.RequestCtx) {
-	scid, _ := c.UserValue("cid").(string)
+	var (
-	prefix, _ := c.UserValue("prefix").(string)
+		scid, _   = c.UserValue("cid").(string)
+		prefix, _ = c.UserValue("prefix").(string)
+		ctx       = utils.GetContextFromRequest(c)
+		log       = utils.WithRequestTracing(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.Uint64("id", c.ID()), 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()))
+	log = log.With(zap.String("cid", scid), zap.String("prefix", prefix), zap.Uint64("id", c.ID()))
-
-	ctx := utils.GetContextFromRequest(c)
 
 	bktInfo, err := h.getBucketInfo(ctx, scid, log)
 	if err != nil {

internal/handler/handler.go

@@ -183,11 +183,13 @@ func (h *Handler) byAddress(c *fasthttp.RequestCtx, f func(context.Context, requ
 	var (
 		idCnr, _ = c.UserValue("cid").(string)
 		idObj, _ = c.UserValue("oid").(string)
-		log      = h.log.With(zap.String("cid", idCnr), zap.String("oid", idObj))
+		ctx      = utils.GetContextFromRequest(c)
+		log      = utils.WithRequestTracing(ctx, h.log.With(
+			zap.String("cid", idCnr),
+			zap.String("oid", idObj),
+		))
 	)
 
-	ctx := utils.GetContextFromRequest(c)
-
 	bktInfo, err := h.getBucketInfo(ctx, idCnr, log)
 	if err != nil {
 		logAndSendBucketError(c, log, err)
@@ -214,8 +216,12 @@ func (h *Handler) byObjectName(c *fasthttp.RequestCtx, f func(context.Context, r
 	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")
+		ctx        = utils.GetContextFromRequest(c)
+		log        = utils.WithRequestTracing(ctx, h.log.With(
+			zap.String("bucketname", bucketname),
+			zap.String("key", key),
+		))
 	)
 
 	unescapedKey, err := url.QueryUnescape(key)
@@ -224,8 +230,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)
@@ -266,27 +270,29 @@ func (h *Handler) byObjectName(c *fasthttp.RequestCtx, f func(context.Context, r
 
 // byAttribute is a wrapper similar to byAddress.
 func (h *Handler) byAttribute(c *fasthttp.RequestCtx, f func(context.Context, request, oid.Address)) {
-	scid, _ := c.UserValue("cid").(string)
+	var (
-	key, _ := c.UserValue("attr_key").(string)
+		scid, _ = c.UserValue("cid").(string)
-	val, _ := c.UserValue("attr_val").(string)
+		key, _  = c.UserValue("attr_key").(string)
+		val, _  = c.UserValue("attr_val").(string)
+		ctx     = utils.GetContextFromRequest(c)
+		log     = utils.WithRequestTracing(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.Uint64("id", c.ID()), 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.Uint64("id", c.ID()), 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))
+	log = log.With(zap.String("cid", scid), zap.String("attr_key", key), zap.String("attr_val", val))
-
-	ctx := utils.GetContextFromRequest(c)
 
 	bktInfo, err := h.getBucketInfo(ctx, scid, log)
 	if err != nil {

internal/handler/upload.go

@@ -49,13 +49,12 @@ func (h *Handler) Upload(c *fasthttp.RequestCtx) {
 		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)
+		ctx        = utils.GetContextFromRequest(c)
+		log        = utils.WithRequestTracing(ctx, h.log.With(zap.String("cid", scid)))
 	)
 
-	ctx := utils.GetContextFromRequest(c)
-
 	bktInfo, err := h.getBucketInfo(ctx, scid, log)
 	if err != nil {
 		logAndSendBucketError(c, log, err)
@@ -75,13 +74,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 +144,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 +175,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)
 }
 

utils/util.go

@@ -4,6 +4,8 @@ import (
 	"context"
 
 	"github.com/valyala/fasthttp"
+	"go.opentelemetry.io/otel/trace"
+	"go.uber.org/zap"
 )
 
 // SetContextToRequest adds new context to fasthttp request.
@@ -15,3 +17,12 @@ func SetContextToRequest(ctx context.Context, c *fasthttp.RequestCtx) {
 func GetContextFromRequest(c *fasthttp.RequestCtx) context.Context {
 	return c.UserValue("context").(context.Context)
 }
+
+// WithTracing adds trace_id field to logs.
+func WithRequestTracing(ctx context.Context, log *zap.Logger) *zap.Logger {
+	if traceID := trace.SpanFromContext(ctx).SpanContext().TraceID(); traceID.IsValid() {
+		return log.With(zap.String("trace_id", traceID.String()))
+	}
+
+	return log
+}