TrueCloudLab/frostfs-http-gw
16
1
Fork 17
Code Issues 8 Pull requests 2 Projects Releases 8 Activity Actions

[#148] Add trace_id to logs #152

Merged
alexvanin merged 1 commit from r.loginov/frostfs-http-gw:feature/148-add_trace_id_to_log into master 2024-10-18 09:29:05 +00:00
Conversation 1 Commits 1 Files changed 7 +104 -48
r.loginov commented 2024-10-08 09:45:47 +00:00
Member
Copy link

close #148

If the tracing is disabled, then the logs are the same as they were before. If tracing is enabled, then trace_id is added to the logs.
Examples of logs with tracing enabled:
The operation of getting an object (without errors)

2024-10-08T12:38:19.139+0300    info    http-gw/app.go:569      request {"remote": "127.0.0.1:37386", "method": "GET", "path": "/get/cats/cat", "query": "", "id": 4294967297, "trace_id": "091d56fee3f855b1e9f5cbbd4114fef1"}

Operation to get an object with an error

2024-10-08T12:43:20.976+0300    info    http-gw/app.go:569      request {"remote": "127.0.0.1:50448", "method": "GET", "path": "/get/catsd/cat", "query": "", "id": 4294967297, "trace_id": "74ef481a16198c42209057c162f182a2"}
2024-10-08T12:43:20.977+0300    error   handler/utils.go:64     could not get bucket    {"bucketname": "catsd", "key": "cat", "trace_id": "74ef481a16198c42209057c162f182a2", "error": "status: code = 3072 message = container not found: nns: couldn't resolve container 'catsd': contract invocation: invocation failed: at instruction 3441 (THROW): unhandled exception: \"token not found\""}
close #148 If the tracing is disabled, then the logs are the same as they were before. If tracing is enabled, then `trace_id` is added to the logs. Examples of logs with tracing enabled: The operation of getting an object (without errors) ``` 2024-10-08T12:38:19.139+0300 info http-gw/app.go:569 request {"remote": "127.0.0.1:37386", "method": "GET", "path": "/get/cats/cat", "query": "", "id": 4294967297, "trace_id": "091d56fee3f855b1e9f5cbbd4114fef1"} ``` Operation to get an object with an error ``` 2024-10-08T12:43:20.976+0300 info http-gw/app.go:569 request {"remote": "127.0.0.1:50448", "method": "GET", "path": "/get/catsd/cat", "query": "", "id": 4294967297, "trace_id": "74ef481a16198c42209057c162f182a2"} 2024-10-08T12:43:20.977+0300 error handler/utils.go:64 could not get bucket {"bucketname": "catsd", "key": "cat", "trace_id": "74ef481a16198c42209057c162f182a2", "error": "status: code = 3072 message = container not found: nns: couldn't resolve container 'catsd': contract invocation: invocation failed: at instruction 3441 (THROW): unhandled exception: \"token not found\""} ```
r.loginov self-assigned this 2024-10-08 09:45:47 +00:00
r.loginov added 1 commit 2024-10-08 09:45:48 +00:00
[#148] Add trace_id to logs
All checks were successful
/ DCO (pull_request) Successful in 1m1s
Details
/ Vulncheck (pull_request) Successful in 1m39s
Details
/ Builds (pull_request) Successful in 1m8s
Details
/ Lint (pull_request) Successful in 2m24s
Details
/ Tests (pull_request) Successful in 1m5s
Details
d2a37a17c4 
Signed-off-by: Roman Loginov <r.loginov@yadro.com>
r.loginov force-pushed feature/148-add_trace_id_to_log from d2a37a17c4 to 78601fef8a 2024-10-08 09:52:41 +00:00 Compare
r.loginov force-pushed feature/148-add_trace_id_to_log from 78601fef8a to b0999f87cf 2024-10-08 10:16:45 +00:00 Compare
r.loginov requested review from alexvanin 2024-10-08 10:22:01 +00:00
r.loginov requested review from dkirillov 2024-10-08 10:22:01 +00:00
r.loginov requested review from pogpp 2024-10-08 10:22:01 +00:00
r.loginov requested review from mbiryukova 2024-10-08 10:22:01 +00:00
r.loginov requested review from nzinkevich 2024-10-08 10:22:02 +00:00
nzinkevich reviewed 2024-10-08 11:24:06 +00:00
cmd/http-gw/app.go Outdated
@ -650,3 +660,3 @@
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)
nzinkevich commented 2024-10-08 11:16:25 +00:00
Member
Copy link

Are there any reasons why we refused getting ctx from a.ctx? If so, let's replace with reqCtx

Are there any reasons why we refused getting ctx from `a.ctx`? If so, let's replace with `reqCtx`
r.loginov commented 2024-10-08 13:28:42 +00:00
Author
Member
Copy link

The reason is that the first middleware that works with context should get context based on appCtx. Previously, the middleware tokenizer was the first handler that featured context, and that's why it didn't use the request context, but used the application context. However, now the first middleware that works with context is tracer. Therefore, tracer gets the context from appCtx, and at the same time tokenizer no longer needs to take the context from appCtx because the necessary information for it will be in the context of the request.
In other words, we want to store the data that is inherent in a specific request (trace information, bearer token) in the context of the request. And we want to make the request context based on the application context.
If I'm wrong or didn't answer the question, let me know.
This comment responds to two comments.

The reason is that the first middleware that works with context should get context based on `appCtx`. Previously, the middleware `tokenizer` was the first handler that featured context, and that's why it didn't use the request context, but used the application context. However, now the first middleware that works with context is `tracer`. Therefore, `tracer` gets the context from `appCtx`, and at the same time `tokenizer` no longer needs to take the context from `appCtx` because the necessary information for it will be in the context of the request. In other words, we want to store the data that is inherent in a specific request (trace information, bearer token) in the context of the request. And we want to make the request context based on the application context. If I'm wrong or didn't answer the question, let me know. This comment responds to two comments.
👍 1
dkirillov commented 2024-10-09 09:24:28 +00:00
Member
Copy link

It seems we can write

reqCtx := utils.GetContextFromRequest(req)
appCtx, err := tokens.StoreBearerTokenAppCtx(reqCtx, req)

This can help don't get again context in line 669

It seems we can write ```golang reqCtx := utils.GetContextFromRequest(req) appCtx, err := tokens.StoreBearerTokenAppCtx(reqCtx, req) ``` This can help don't get again context in line 669
👍 1
cmd/http-gw/app.go Outdated
@ -665,3 +685,1 @@
appCtx := utils.GetContextFromRequest(req)
appCtx, span := utils.StartHTTPServerSpan(appCtx, req, "REQUEST")
appCtx, span := utils.StartHTTPServerSpan(a.ctx, req, "REQUEST")
nzinkevich commented 2024-10-08 11:18:13 +00:00
Member
Copy link

opposite situation - we start getting context from a.ctx. Are they equal? I think it'd be better to get context the same way in all places

opposite situation - we start getting context from `a.ctx`. Are they equal? I think it'd be better to get context the same way in all places
internal/handler/browse.go Outdated
@ -118,0 +119,4 @@
if traceID := trace.SpanFromContext(ctx).SpanContext().TraceID(); traceID.IsValid() {
log = log.With(zap.String("trace_id", traceID.String()))
}
nzinkevich commented 2024-10-08 11:06:16 +00:00
Member
Copy link

I think we can extract these repeating conditions to a separate function - it occurs 8 times

I think we can extract these repeating conditions to a separate function - it occurs 8 times
👍 1
r.loginov commented 2024-10-09 09:29:47 +00:00
Author
Member
Copy link

done
I also thought about using this version of the function, but it didn't seem very flexible to me. What do you think?

func WithCustomFields(ctx context.Context, log *zap.Logger, fields ...zap.Field) *zap.Logger {
	if traceID := trace.SpanFromContext(ctx).SpanContext().TraceID(); traceID.IsValid() {
		fields = append(fields, zap.String("trace_id", traceID.String()))
	}

	return log.With(fields...)
}
done I also thought about using this version of the function, but it didn't seem very flexible to me. What do you think? ``` func WithCustomFields(ctx context.Context, log *zap.Logger, fields ...zap.Field) *zap.Logger { if traceID := trace.SpanFromContext(ctx).SpanContext().TraceID(); traceID.IsValid() { fields = append(fields, zap.String("trace_id", traceID.String())) } return log.With(fields...) } ```
r.loginov force-pushed feature/148-add_trace_id_to_log from b0999f87cf to e124c8fd2d 2024-10-09 09:22:43 +00:00 Compare
dkirillov reviewed 2024-10-09 09:39:46 +00:00
CHANGELOG.md Outdated
@ -6,1 +6,4 @@
### Added
- Support percent-encoding for GET queries (#134)
- Add `trace_id` to logs (#152)
dkirillov commented 2024-10-09 09:18:22 +00:00
Member
Copy link

It's better to use issue link if it exists (#148)

It's better to use issue link if it exists (#148)
👍 1
dkirillov marked this conversation as resolved
cmd/http-gw/app.go Outdated
@ -614,0 +617,4 @@
appCtx := utils.GetContextFromRequest(req)
log := utils.WithRequestTracing(appCtx, a.log)
log.Info(logs.Request, fields...)
dkirillov commented 2024-10-09 09:39:28 +00:00
Member
Copy link

Consider something like this

diff --git a/cmd/http-gw/app.go b/cmd/http-gw/app.go
index 007a8d7..de01f75 100644
--- a/cmd/http-gw/app.go
+++ b/cmd/http-gw/app.go
@@ -607,20 +607,24 @@ func (a *app) configureRouter(handler *handler.Handler) {
 
 func (a *app) logger(h fasthttp.RequestHandler) fasthttp.RequestHandler {
 	return func(req *fasthttp.RequestCtx) {
+		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()),
 		}
 
-		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...)
+		log.Info(logs.Request, fields...)
 		h(req)
 	}
 }
@@ -659,19 +663,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(utils.GetContextFromRequest(req), req)
+		reqCtx := utils.GetContextFromRequest(req)
+
+		appCtx, err := tokens.StoreBearerTokenAppCtx(reqCtx, req)
 		if err != nil {
 			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...)
+			log := utils.GetReqLogOrDefault(reqCtx, a.log)
+			log.Error(logs.CouldNotFetchAndStoreBearerToken, fields...)
 			response.Error(req, "could not fetch and store bearer token: "+err.Error(), fasthttp.StatusBadRequest)
 			return
 		}
diff --git a/utils/util.go b/utils/util.go
index d513817..dd00d38 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,29 @@ func SetContextToRequest(ctx context.Context, c *fasthttp.RequestCtx) {
 func GetContextFromRequest(c *fasthttp.RequestCtx) context.Context {
 	return c.UserValue("context").(context.Context)
 }
+
+type ctxReqLoggerKeyType struct{}
+
+func SetReqLog(ctx context.Context, log *zap.Logger) context.Context {
+	if ctx == nil {
+		return nil
+	}
+	return context.WithValue(ctx, ctxReqLoggerKeyType{}, log)
+}
+
+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
+}
+
+func GetReqLogOrDefault(ctx context.Context, defaultLog *zap.Logger) *zap.Logger {
+	log := GetReqLog(ctx)
+	if log == nil {
+		log = defaultLog
+	}
+	return log
+}
Consider something like this ```diff diff --git a/cmd/http-gw/app.go b/cmd/http-gw/app.go index 007a8d7..de01f75 100644 --- a/cmd/http-gw/app.go +++ b/cmd/http-gw/app.go @@ -607,20 +607,24 @@ func (a *app) configureRouter(handler *handler.Handler) { func (a *app) logger(h fasthttp.RequestHandler) fasthttp.RequestHandler { return func(req *fasthttp.RequestCtx) { + 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()), } - 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...) + log.Info(logs.Request, fields...) h(req) } } @@ -659,19 +663,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(utils.GetContextFromRequest(req), req) + reqCtx := utils.GetContextFromRequest(req) + + appCtx, err := tokens.StoreBearerTokenAppCtx(reqCtx, req) if err != nil { 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...) + log := utils.GetReqLogOrDefault(reqCtx, a.log) + log.Error(logs.CouldNotFetchAndStoreBearerToken, fields...) response.Error(req, "could not fetch and store bearer token: "+err.Error(), fasthttp.StatusBadRequest) return } diff --git a/utils/util.go b/utils/util.go index d513817..dd00d38 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,29 @@ func SetContextToRequest(ctx context.Context, c *fasthttp.RequestCtx) { func GetContextFromRequest(c *fasthttp.RequestCtx) context.Context { return c.UserValue("context").(context.Context) } + +type ctxReqLoggerKeyType struct{} + +func SetReqLog(ctx context.Context, log *zap.Logger) context.Context { + if ctx == nil { + return nil + } + return context.WithValue(ctx, ctxReqLoggerKeyType{}, log) +} + +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 +} + +func GetReqLogOrDefault(ctx context.Context, defaultLog *zap.Logger) *zap.Logger { + log := GetReqLog(ctx) + if log == nil { + log = defaultLog + } + return log +} ```
👍 2
dkirillov marked this conversation as resolved
r.loginov force-pushed feature/148-add_trace_id_to_log from e124c8fd2d to f2c52bf379 2024-10-09 15:02:20 +00:00 Compare
nzinkevich approved these changes 2024-10-10 06:48:32 +00:00
Dismissed
dkirillov reviewed 2024-10-11 12:55:22 +00:00
internal/handler/browse.go Outdated
@ -118,0 +116,4 @@
var (
ctx = utils.GetContextFromRequest(c)
reqLog = utils.GetReqLogOrDefault(ctx, h.log)
log = reqLog.With(zap.String("bucket", bucketInfo.Name))
dkirillov commented 2024-10-11 12:55:22 +00:00
Member
Copy link

Why don't we write

ctx := utils.GetContextFromRequest(c)
reqLog := utils.GetReqLogOrDefault(ctx, h.log)
log := reqLog.With(zap.String("bucket", bucketInfo.Name))

?

Why don't we write ```golang ctx := utils.GetContextFromRequest(c) reqLog := utils.GetReqLogOrDefault(ctx, h.log) log := reqLog.With(zap.String("bucket", bucketInfo.Name)) ``` ?
dkirillov marked this conversation as resolved
dkirillov reviewed 2024-10-11 12:55:47 +00:00
internal/handler/download.go Outdated
@ -86,0 +85,4 @@
scid, _ = c.UserValue("cid").(string)
prefix, _ = c.UserValue("prefix").(string)
ctx = utils.GetContextFromRequest(c)
log = utils.GetReqLogOrDefault(ctx, h.log)
dkirillov commented 2024-10-11 12:55:47 +00:00
Member
Copy link

The same as previous comment

The same as previous comment
dkirillov marked this conversation as resolved
dkirillov reviewed 2024-10-11 12:56:52 +00:00
internal/handler/download.go Outdated
@ -87,3 +91,3 @@
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))
dkirillov commented 2024-10-11 12:56:52 +00:00
Member
Copy link

I suppose we can skip additional adding id to log because we use logger from context

log.Error(logs.FailedToUnescapeQuery, zap.String("cid", scid), zap.String("prefix", prefix), zap.Error(err))
I suppose we can skip additional adding id to log because we use logger from context ```golang log.Error(logs.FailedToUnescapeQuery, zap.String("cid", scid), zap.String("prefix", prefix), zap.Error(err)) ```
dkirillov marked this conversation as resolved
dkirillov reviewed 2024-10-11 12:58:00 +00:00
internal/handler/download.go Outdated
@ -94,3 +98,1 @@
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()))
dkirillov commented 2024-10-11 12:58:00 +00:00
Member
Copy link

The same

log = log.With(zap.String("cid", scid), zap.String("prefix", prefix)
The same ```golang log = log.With(zap.String("cid", scid), zap.String("prefix", prefix) ```
dkirillov marked this conversation as resolved
r.loginov force-pushed feature/148-add_trace_id_to_log from f2c52bf379 to 3768efc50b 2024-10-14 06:56:03 +00:00 Compare
r.loginov dismissed nzinkevich's review 2024-10-14 06:56:03 +00:00
Reason:

New commits pushed, approval review dismissed automatically according to repository settings

alexvanin approved these changes 2024-10-14 11:53:08 +00:00
Dismissed
dkirillov approved these changes 2024-10-15 06:25:38 +00:00
Dismissed
alexvanin commented 2024-10-15 06:48:24 +00:00
Owner
Copy link

Going to merge after #143

Going to merge after https://git.frostfs.info/TrueCloudLab/frostfs-http-gw/pulls/143
alexvanin force-pushed feature/148-add_trace_id_to_log from 3768efc50b to fc86ab3511 2024-10-17 11:00:46 +00:00 Compare
alexvanin dismissed alexvanin's review 2024-10-17 11:00:47 +00:00
Reason:

New commits pushed, approval review dismissed automatically according to repository settings

alexvanin dismissed dkirillov's review 2024-10-17 11:00:47 +00:00
Reason:

New commits pushed, approval review dismissed automatically according to repository settings

dkirillov approved these changes 2024-10-17 14:04:18 +00:00
alexvanin merged commit fc86ab3511 into master 2024-10-18 09:29:05 +00:00
alexvanin deleted branch feature/148-add_trace_id_to_log 2024-10-18 09:29:08 +00:00
Sign in to join this conversation.
Reviewers
No reviewers
pogpp
mbiryukova
dkirillov
Labels
Clear labels   
P0

Highest

  
P1

High

  
P2

Medium

  
P3

Low

  
good first issue

Good for newcomers

  
Infrastructure

Infrastructure, Automation, CI/CD or DevOps related stuff

  
blocked

The issue or PR is blocked by something

  
bug

Something is not working

  
config

Configuration format update or breaking change

  
discussion

Talking about something in order to reach a decision or to exchange ideas

  
documentation

Documentation related

  
duplicate

This issue or pull request already exists

  
enhancement

New feature

  
go

Language features adoption

  
help wanted

Extra attention is needed

  
internal

   
invalid

Something is wrong

  
kludge

This is a kludge and we know it

  
observability

Related to metrics, tracing and logs

  
perfomance

Perfomance related

  
question

More information is needed

  
refactoring

Refactoring

  
wontfix

This won't be fixed

No labels
P0
P1
P2
P3
good first issue
Infrastructure
blocked
bug
config
discussion
documentation
duplicate
enhancement
go
help wanted
internal
invalid
kludge
observability
perfomance
question
refactoring
wontfix
Milestone
Clear milestone
No items
No milestone
Projects
Clear projects
No items
No project
Assignees
Clear assignees
No assignees
r.loginov
4 participants
Notifications
Due date
The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set.

Reference: TrueCloudLab/frostfs-http-gw#152
No description provided.
Delete branch "r.loginov/frostfs-http-gw:feature/148-add_trace_id_to_log"

Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?