[#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

@@ -43,6 +43,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"
 )
@@ -590,15 +591,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 +607,20 @@ 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)
+		if traceID := trace.SpanFromContext(appCtx).SpanContext().TraceID(); traceID.IsValid() {
+			fields = append(fields, zap.String("trace_id", traceID.String()))
+		}
+
+		a.log.Info(logs.Request, fields...)
 		h(req)
 	}
 }
@@ -649,9 +659,19 @@ 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)
+			if traceID := trace.SpanFromContext(reqCtx).SpanContext().TraceID(); traceID.IsValid() {
+				fields = append(fields, zap.String("trace_id", traceID.String()))
+			}
+
+			a.log.Error(logs.CouldNotFetchAndStoreBearerToken, fields...)
 			response.Error(req, "could not fetch and store bearer token: "+err.Error(), fasthttp.StatusBadRequest)
 			return
 		}
@@ -662,9 +682,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

@@ -12,6 +12,7 @@ import (
 	"git.frostfs.info/TrueCloudLab/frostfs-http-gw/utils"
 	"github.com/docker/go-units"
 	"github.com/valyala/fasthttp"
+	"go.opentelemetry.io/otel/trace"
 	"go.uber.org/zap"
 )
 
@@ -115,6 +116,11 @@ 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)
+
+	if traceID := trace.SpanFromContext(ctx).SpanContext().TraceID(); traceID.IsValid() {
+		log = log.With(zap.String("trace_id", traceID.String()))
+	}
+
 	nodes, err := h.listObjects(ctx, bucketInfo, prefix)
 	if err != nil {
 		logAndSendBucketError(c, log, err)

internal/handler/download.go

@@ -18,6 +18,7 @@ import (
 	"git.frostfs.info/TrueCloudLab/frostfs-sdk-go/object"
 	oid "git.frostfs.info/TrueCloudLab/frostfs-sdk-go/object/id"
 	"github.com/valyala/fasthttp"
+	"go.opentelemetry.io/otel/trace"
 	"go.uber.org/zap"
 )
 
@@ -81,19 +82,25 @@ 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)
+		log       = h.log
+		ctx       = utils.GetContextFromRequest(c)
+	)
+
+	if traceID := trace.SpanFromContext(ctx).SpanContext().TraceID(); traceID.IsValid() {
+		log = log.With(zap.String("trace_id", traceID.String()))
+	}
 
 	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

@@ -23,6 +23,7 @@ import (
 	oid "git.frostfs.info/TrueCloudLab/frostfs-sdk-go/object/id"
 	"git.frostfs.info/TrueCloudLab/frostfs-sdk-go/user"
 	"github.com/valyala/fasthttp"
+	"go.opentelemetry.io/otel/trace"
 	"go.uber.org/zap"
 )
 
@@ -184,9 +185,12 @@ func (h *Handler) byAddress(c *fasthttp.RequestCtx, f func(context.Context, requ
 		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)
 	)
 
-	ctx := utils.GetContextFromRequest(c)
+	if traceID := trace.SpanFromContext(ctx).SpanContext().TraceID(); traceID.IsValid() {
+		log = log.With(zap.String("trace_id", traceID.String()))
+	}
 
 	bktInfo, err := h.getBucketInfo(ctx, idCnr, log)
 	if err != nil {
@@ -216,16 +220,19 @@ func (h *Handler) byObjectName(c *fasthttp.RequestCtx, f func(context.Context, r
 		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)
 	)
 
+	if traceID := trace.SpanFromContext(ctx).SpanContext().TraceID(); traceID.IsValid() {
+		log = log.With(zap.String("trace_id", traceID.String()))
+	}
+
 	unescapedKey, err := url.QueryUnescape(key)
 	if err != nil {
 		logAndSendBucketError(c, log, err)
 		return
 	}
 
-	ctx := utils.GetContextFromRequest(c)
-
 	bktInfo, err := h.getBucketInfo(ctx, bucketname, log)
 	if err != nil {
 		logAndSendBucketError(c, log, err)
@@ -266,27 +273,33 @@ 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)
+		log     = h.log
+		ctx     = utils.GetContextFromRequest(c)
+	)
+
+	if traceID := trace.SpanFromContext(ctx).SpanContext().TraceID(); traceID.IsValid() {
+		log = log.With(zap.String("trace_id", traceID.String()))
+	}
 
 	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

@@ -16,6 +16,7 @@ import (
 	"git.frostfs.info/TrueCloudLab/frostfs-sdk-go/object"
 	oid "git.frostfs.info/TrueCloudLab/frostfs-sdk-go/object/id"
 	"github.com/valyala/fasthttp"
+	"go.opentelemetry.io/otel/trace"
 	"go.uber.org/zap"
 )
 
@@ -52,9 +53,12 @@ func (h *Handler) Upload(c *fasthttp.RequestCtx) {
 		log        = h.log.With(zap.String("cid", scid))
 		bodyStream = c.RequestBodyStream()
 		drainBuf   = make([]byte, drainBufSize)
+		ctx        = utils.GetContextFromRequest(c)
 	)
 
-	ctx := utils.GetContextFromRequest(c)
+	if traceID := trace.SpanFromContext(ctx).SpanContext().TraceID(); traceID.IsValid() {
+		log = log.With(zap.String("trace_id", traceID.String()))
+	}
 
 	bktInfo, err := h.getBucketInfo(ctx, scid, log)
 	if err != nil {
@@ -75,13 +79,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 +149,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 +180,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)
 }