From f2c52bf37977f817ff273106b9ea76f07d847648 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 | 8 +++++-- internal/handler/download.go | 14 ++++++------ internal/handler/handler.go | 30 ++++++++++++++------------ internal/handler/upload.go | 18 +++++++++------- utils/util.go | 32 ++++++++++++++++++++++++++++ 7 files changed, 103 insertions(+), 43 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 8d5930d..9e15a94 100644 --- a/cmd/http-gw/app.go +++ b/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.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 @@ -606,11 +607,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) } } @@ -649,9 +663,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 } @@ -662,9 +679,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..46a37dd 100644 --- a/internal/handler/browse.go +++ b/internal/handler/browse.go @@ -113,8 +113,12 @@ 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) + var ( + 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..88bb729 100644 --- a/internal/handler/download.go +++ b/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) - prefix, _ := c.UserValue("prefix").(string) + var ( + 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.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 8b07af0..530f8ff 100644 --- a/internal/handler/handler.go +++ b/internal/handler/handler.go @@ -183,11 +183,11 @@ 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) + reqLog = utils.GetReqLogOrDefault(ctx, h.log) + log = reqLog.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 +214,10 @@ 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) + reqLog = utils.GetReqLogOrDefault(ctx, h.log) + log = reqLog.With(zap.String("bucketname", bucketname), zap.String("key", key)) ) unescapedKey, err := url.QueryUnescape(key) @@ -224,8 +226,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 +266,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) - 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) + 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.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 6c0e117..d89fef8 100644 --- a/internal/handler/upload.go +++ b/internal/handler/upload.go @@ -49,13 +49,13 @@ 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) + reqLog = utils.GetReqLogOrDefault(ctx, h.log) + log = reqLog.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 +75,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 +145,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 +176,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 +}