From d2a37a17c4fd2092b87e14ace3de0724df8a1502 Mon Sep 17 00:00:00 2001 From: Roman Loginov Date: Tue, 8 Oct 2024 12:08:39 +0300 Subject: [PATCH] [#148] Add trace_id to logs Signed-off-by: Roman Loginov --- CHANGELOG.md | 3 +++ cmd/http-gw/app.go | 44 +++++++++++++++++++++++++----------- internal/handler/download.go | 19 +++++++++++----- internal/handler/handler.go | 35 +++++++++++++++++++--------- internal/handler/upload.go | 16 ++++++++----- 5 files changed, 81 insertions(+), 36 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index a489027..cd45898 100644 --- 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 (##) ### Changed - Update go version to 1.22 (#132) diff --git a/cmd/http-gw/app.go b/cmd/http-gw/app.go index 4c49ee4..a1f56cc 100644 --- a/cmd/http-gw/app.go +++ b/cmd/http-gw/app.go @@ -41,6 +41,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" ) @@ -536,15 +537,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 @@ -552,11 +553,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) } } @@ -595,9 +605,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 } @@ -608,9 +628,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() diff --git a/internal/handler/download.go b/internal/handler/download.go index 88109a6..a7e88eb 100644 --- a/internal/handler/download.go +++ b/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) - prefix, _ := c.UserValue("prefix").(string) + var ( + 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())) - - ctx := utils.GetContextFromRequest(c) + log = log.With(zap.String("cid", scid), zap.String("prefix", prefix), zap.Uint64("id", c.ID())) bktInfo, err := h.getBucketInfo(ctx, scid, log) if err != nil { diff --git a/internal/handler/handler.go b/internal/handler/handler.go index 4de9d9a..a9bc597 100644 --- a/internal/handler/handler.go +++ b/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" ) @@ -182,9 +183,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 { @@ -213,16 +217,19 @@ func (h *Handler) byObjectName(req *fasthttp.RequestCtx, f func(context.Context, bucketname = req.UserValue("cid").(string) key = req.UserValue("oid").(string) log = h.log.With(zap.String("bucketname", bucketname), zap.String("key", key)) + ctx = utils.GetContextFromRequest(req) ) + 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(req, log, err) return } - ctx := utils.GetContextFromRequest(req) - bktInfo, err := h.getBucketInfo(ctx, bucketname, log) if err != nil { logAndSendBucketError(req, log, err) @@ -255,27 +262,33 @@ func (h *Handler) byObjectName(req *fasthttp.RequestCtx, f func(context.Context, // 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) - key, _ := c.UserValue("attr_key").(string) - val, _ := c.UserValue("attr_val").(string) + var ( + scid, _ = c.UserValue("cid").(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)) - - 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 { diff --git a/internal/handler/upload.go b/internal/handler/upload.go index cea2250..30ed2da 100644 --- a/internal/handler/upload.go +++ b/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(req *fasthttp.RequestCtx) { log = h.log.With(zap.String("cid", scid)) bodyStream = req.RequestBodyStream() drainBuf = make([]byte, drainBufSize) + ctx = utils.GetContextFromRequest(req) ) - ctx := utils.GetContextFromRequest(req) + 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 { @@ -76,12 +80,12 @@ func (h *Handler) Upload(req *fasthttp.RequestCtx) { ) }() boundary := string(req.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(req, "could not receive multipart/form: "+err.Error(), fasthttp.StatusBadRequest) return } - filtered, err := filterHeaders(h.log, &req.Request.Header) + filtered, err := filterHeaders(log, &req.Request.Header) if err != nil { log.Error(logs.CouldNotProcessHeaders, zap.Error(err)) response.Error(req, err.Error(), fasthttp.StatusBadRequest) @@ -143,7 +147,7 @@ func (h *Handler) Upload(req *fasthttp.RequestCtx) { } if idObj, err = h.frostfs.CreateObject(ctx, prm); err != nil { - h.handlePutFrostFSErr(req, err) + h.handlePutFrostFSErr(req, err, log) return } @@ -174,11 +178,11 @@ func (h *Handler) Upload(req *fasthttp.RequestCtx) { req.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) }