From fc86ab3511a153b30b7ff45b15ff5865405786ca 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 | 41 ++++++++++++++++++++++++------------ internal/handler/browse.go | 4 +++- internal/handler/download.go | 9 ++++---- internal/handler/handler.go | 35 +++++++++++++++--------------- internal/handler/upload.go | 28 +++++++++++++----------- utils/util.go | 32 ++++++++++++++++++++++++++++ 7 files changed, 104 insertions(+), 48 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index a489027..46e9c23 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 (#148) ### Changed - Update go version to 1.22 (#132) diff --git a/cmd/http-gw/app.go b/cmd/http-gw/app.go index f8300ec..b26df89 100644 --- 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() diff --git a/internal/handler/browse.go b/internal/handler/browse.go index e84fb04..c89d8c5 100644 --- 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) diff --git a/internal/handler/download.go b/internal/handler/download.go index 88109a6..19380d4 100644 --- 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 { diff --git a/internal/handler/handler.go b/internal/handler/handler.go index c680706..62d0897 100644 --- 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 { diff --git a/internal/handler/upload.go b/internal/handler/upload.go index 6c0e117..867025d 100644 --- 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) } diff --git a/utils/util.go b/utils/util.go index d513817..b7f5e39 100644 --- 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 +}