From 90c128e7a66389477943bbca080ce68a70196310 Mon Sep 17 00:00:00 2001 From: Aleksey Kosov Date: Fri, 20 Jun 2025 16:23:53 +0300 Subject: [PATCH] Context-based logging with request ID (#6899) --- weed/glog/glog_ctx.go | 246 +++++++++++++++++++++ weed/operation/upload_content.go | 6 +- weed/pb/grpc_client_server.go | 15 +- weed/server/common.go | 20 +- weed/server/filer_server_handlers_proxy.go | 5 +- weed/util/http/http_global_client_util.go | 5 +- weed/util/request_id.go | 27 --- weed/util/request_id/request_id.go | 26 +++ 8 files changed, 302 insertions(+), 48 deletions(-) create mode 100644 weed/glog/glog_ctx.go delete mode 100644 weed/util/request_id.go create mode 100644 weed/util/request_id/request_id.go diff --git a/weed/glog/glog_ctx.go b/weed/glog/glog_ctx.go new file mode 100644 index 000000000..daae3b148 --- /dev/null +++ b/weed/glog/glog_ctx.go @@ -0,0 +1,246 @@ +package glog + +import ( + "context" + "fmt" + "sync/atomic" + + reqid "github.com/seaweedfs/seaweedfs/weed/util/request_id" +) + +const requestIDField = "request_id" + +// formatMetaTag returns a formatted request ID tag from the context, +// like "request_id:abc123". Returns an empty string if no request ID is found. +func formatMetaTag(ctx context.Context) string { + if requestID := reqid.Get(ctx); requestID != "" { + return fmt.Sprintf("%s:%s", requestIDField, requestID) + } + return "" +} + +// InfoCtx is a context-aware alternative to Verbose.Info. +// Logs to the INFO log, guarded by the value of v, and prepends a request ID from the context if present. +// Arguments are handled in the manner of fmt.Print. +func (v Verbose) InfoCtx(ctx context.Context, args ...interface{}) { + if !v { + return + } + if metaTag := formatMetaTag(ctx); metaTag != "" { + args = append([]interface{}{metaTag}, args...) + } + logging.print(infoLog, args...) +} + +// InfolnCtx is a context-aware alternative to Verbose.Infoln. +// Logs to the INFO log, prepending a request ID from the context if it exists. +// Arguments are handled in the manner of fmt.Println. +func (v Verbose) InfolnCtx(ctx context.Context, args ...interface{}) { + if !v { + return + } + if metaTag := formatMetaTag(ctx); metaTag != "" { + args = append([]interface{}{metaTag}, args...) + } + logging.println(infoLog, args...) +} + +// InfofCtx is a context-aware alternative to Verbose.Infof. +// Logs to the INFO log, guarded by the value of v, and prepends a request ID from the context if present. +// Arguments are handled in the manner of fmt.Printf. +func (v Verbose) InfofCtx(ctx context.Context, format string, args ...interface{}) { + if !v { + return + } + if metaTag := formatMetaTag(ctx); metaTag != "" { + format = metaTag + " " + format + } + logging.printf(infoLog, format, args...) +} + +// InfofCtx logs a formatted message at info level, prepending a request ID from +// the context if it exists. This is a context-aware alternative to Infof. +func InfofCtx(ctx context.Context, format string, args ...interface{}) { + if metaTag := formatMetaTag(ctx); metaTag != "" { + format = metaTag + " " + format + } + logging.printf(infoLog, format, args...) +} + +// InfoCtx logs a message at info level, prepending a request ID from the context +// if it exists. This is a context-aware alternative to Info. +func InfoCtx(ctx context.Context, args ...interface{}) { + if metaTag := formatMetaTag(ctx); metaTag != "" { + args = append([]interface{}{metaTag}, args...) + } + logging.print(infoLog, args...) +} + +// WarningCtx logs to the WARNING and INFO logs. +// Prepends a request ID from the context if it exists. Arguments are handled in the manner of fmt.Print. +// This is a context-aware alternative to Warning. +func WarningCtx(ctx context.Context, args ...interface{}) { + if metaTag := formatMetaTag(ctx); metaTag != "" { + args = append([]interface{}{metaTag}, args...) + } + logging.print(warningLog, args...) +} + +// WarningDepthCtx logs to the WARNING and INFO logs with a custom call depth. +// Prepends a request ID from the context if it exists. Arguments are handled in the manner of fmt.Print. +// This is a context-aware alternative to WarningDepth. +func WarningDepthCtx(ctx context.Context, depth int, args ...interface{}) { + if metaTag := formatMetaTag(ctx); metaTag != "" { + args = append([]interface{}{metaTag}, args...) + } + logging.printDepth(warningLog, depth, args...) +} + +// WarninglnCtx logs to the WARNING and INFO logs. +// Prepends a request ID from the context if it exists. Arguments are handled in the manner of fmt.Println. +// This is a context-aware alternative to Warningln. +func WarninglnCtx(ctx context.Context, args ...interface{}) { + if metaTag := formatMetaTag(ctx); metaTag != "" { + args = append([]interface{}{metaTag}, args...) + } + logging.println(warningLog, args...) +} + +// WarningfCtx logs to the WARNING and INFO logs. +// Prepends a request ID from the context if it exists. Arguments are handled in the manner of fmt.Printf. +// This is a context-aware alternative to Warningf. +func WarningfCtx(ctx context.Context, format string, args ...interface{}) { + if metaTag := formatMetaTag(ctx); metaTag != "" { + format = metaTag + " " + format + } + logging.printf(warningLog, format, args...) +} + +// ErrorCtx logs to the ERROR, WARNING, and INFO logs. +// Prepends a request ID from the context if it exists. Arguments are handled in the manner of fmt.Print. +// This is a context-aware alternative to Error. +func ErrorCtx(ctx context.Context, args ...interface{}) { + if metaTag := formatMetaTag(ctx); metaTag != "" { + args = append([]interface{}{metaTag}, args...) + } + logging.print(errorLog, args...) +} + +// ErrorDepthCtx logs to the ERROR, WARNING, and INFO logs with a custom call depth. +// Prepends a request ID from the context if it exists. Arguments are handled in the manner of fmt.Print. +// This is a context-aware alternative to ErrorDepth. +func ErrorDepthCtx(ctx context.Context, depth int, args ...interface{}) { + if metaTag := formatMetaTag(ctx); metaTag != "" { + args = append([]interface{}{metaTag}, args...) + } + logging.printDepth(errorLog, depth, args...) +} + +// ErrorlnCtx logs to the ERROR, WARNING, and INFO logs. +// Prepends a request ID from the context if it exists. Arguments are handled in the manner of fmt.Println. +// This is a context-aware alternative to Errorln. +func ErrorlnCtx(ctx context.Context, args ...interface{}) { + if metaTag := formatMetaTag(ctx); metaTag != "" { + args = append([]interface{}{metaTag}, args...) + } + logging.println(errorLog, args...) +} + +// ErrorfCtx logs to the ERROR, WARNING, and INFO logs. +// Prepends a request ID from the context if it exists. Arguments are handled in the manner of fmt.Printf. +// This is a context-aware alternative to Errorf. +func ErrorfCtx(ctx context.Context, format string, args ...interface{}) { + if metaTag := formatMetaTag(ctx); metaTag != "" { + format = metaTag + " " + format + } + logging.printf(errorLog, format, args...) +} + +// FatalCtx logs to the FATAL, ERROR, WARNING, and INFO logs, +// including a stack trace of all running goroutines, then calls os.Exit(255). +// Prepends a request ID from the context if it exists. Arguments are handled in the manner of fmt.Print. +// This is a context-aware alternative to Fatal. +func FatalCtx(ctx context.Context, args ...interface{}) { + if metaTag := formatMetaTag(ctx); metaTag != "" { + args = append([]interface{}{metaTag}, args...) + } + logging.print(fatalLog, args...) +} + +// FatalDepthCtx logs to the FATAL, ERROR, WARNING, and INFO logs with a custom call depth, +// including a stack trace of all running goroutines, then calls os.Exit(255). +// Prepends a request ID from the context if it exists. Arguments are handled in the manner of fmt.Print. +// This is a context-aware alternative to FatalDepth. +func FatalDepthCtx(ctx context.Context, depth int, args ...interface{}) { + if metaTag := formatMetaTag(ctx); metaTag != "" { + args = append([]interface{}{metaTag}, args...) + } + logging.printDepth(fatalLog, depth, args...) +} + +// FatallnCtx logs to the FATAL, ERROR, WARNING, and INFO logs, +// including a stack trace of all running goroutines, then calls os.Exit(255). +// Prepends a request ID from the context if it exists. Arguments are handled in the manner of fmt.Println. +// This is a context-aware alternative to Fatalln. +func FatallnCtx(ctx context.Context, args ...interface{}) { + if metaTag := formatMetaTag(ctx); metaTag != "" { + args = append([]interface{}{metaTag}, args...) + } + logging.println(fatalLog, args...) +} + +// FatalfCtx logs to the FATAL, ERROR, WARNING, and INFO logs, +// including a stack trace of all running goroutines, then calls os.Exit(255). +// Prepends a request ID from the context if it exists. Arguments are handled in the manner of fmt.Printf. +// This is a context-aware alternative to Fatalf. +func FatalfCtx(ctx context.Context, format string, args ...interface{}) { + if metaTag := formatMetaTag(ctx); metaTag != "" { + format = metaTag + " " + format + } + logging.printf(fatalLog, format, args...) +} + +// ExitCtx logs to the FATAL, ERROR, WARNING, and INFO logs, then calls os.Exit(1). +// Prepends a request ID from the context if it exists. Arguments are handled in the manner of fmt.Print. +// This is a context-aware alternative to ExitCtx +func ExitCtx(ctx context.Context, args ...interface{}) { + atomic.StoreUint32(&fatalNoStacks, 1) + if metaTag := formatMetaTag(ctx); metaTag != "" { + args = append([]interface{}{metaTag}, args...) + } + logging.print(fatalLog, args...) +} + +// ExitDepthCtx logs to the FATAL, ERROR, WARNING, and INFO logs with a custom call depth, +// then calls os.Exit(1). Prepends a request ID from the context if it exists. +// Arguments are handled in the manner of fmt.Print. +// This is a context-aware alternative to ExitDepth. +func ExitDepthCtx(ctx context.Context, depth int, args ...interface{}) { + atomic.StoreUint32(&fatalNoStacks, 1) + if metaTag := formatMetaTag(ctx); metaTag != "" { + args = append([]interface{}{metaTag}, args...) + } + logging.printDepth(fatalLog, depth, args...) +} + +// ExitlnCtx logs to the FATAL, ERROR, WARNING, and INFO logs, then calls os.Exit(1). +// Prepends a request ID from the context if it exists. Arguments are handled in the manner of fmt.Println. +// This is a context-aware alternative to Exitln. +func ExitlnCtx(ctx context.Context, args ...interface{}) { + atomic.StoreUint32(&fatalNoStacks, 1) + if metaTag := formatMetaTag(ctx); metaTag != "" { + args = append([]interface{}{metaTag}, args...) + } + logging.println(fatalLog, args...) +} + +// ExitfCtx logs to the FATAL, ERROR, WARNING, and INFO logs, then calls os.Exit(1). +// Prepends a request ID from the context if it exists. Arguments are handled in the manner of fmt.Printf. +// This is a context-aware alternative to Exitf. +func ExitfCtx(ctx context.Context, format string, args ...interface{}) { + atomic.StoreUint32(&fatalNoStacks, 1) + if metaTag := formatMetaTag(ctx); metaTag != "" { + format = metaTag + " " + format + } + logging.printf(fatalLog, format, args...) +} diff --git a/weed/operation/upload_content.go b/weed/operation/upload_content.go index 6d910674b..ac549ef6e 100644 --- a/weed/operation/upload_content.go +++ b/weed/operation/upload_content.go @@ -5,7 +5,6 @@ import ( "context" "encoding/json" "fmt" - "github.com/valyala/bytebufferpool" "io" "mime" "mime/multipart" @@ -16,6 +15,9 @@ import ( "sync" "time" + "github.com/seaweedfs/seaweedfs/weed/util/request_id" + "github.com/valyala/bytebufferpool" + "github.com/seaweedfs/seaweedfs/weed/glog" "github.com/seaweedfs/seaweedfs/weed/pb/filer_pb" "github.com/seaweedfs/seaweedfs/weed/security" @@ -359,7 +361,7 @@ func (uploader *Uploader) upload_content(ctx context.Context, fillBufferFunction req.Header.Set("Authorization", "BEARER "+string(option.Jwt)) } - util.ReqWithRequestId(req, ctx) + request_id.InjectToRequest(ctx, req) // print("+") resp, post_err := uploader.httpClient.Do(req) diff --git a/weed/pb/grpc_client_server.go b/weed/pb/grpc_client_server.go index f179cc3a7..d88c0ce3d 100644 --- a/weed/pb/grpc_client_server.go +++ b/weed/pb/grpc_client_server.go @@ -3,8 +3,6 @@ package pb import ( "context" "fmt" - "github.com/google/uuid" - "google.golang.org/grpc/metadata" "math/rand/v2" "net/http" "strconv" @@ -12,6 +10,10 @@ import ( "sync" "time" + "github.com/google/uuid" + "github.com/seaweedfs/seaweedfs/weed/util/request_id" + "google.golang.org/grpc/metadata" + "github.com/seaweedfs/seaweedfs/weed/glog" "github.com/seaweedfs/seaweedfs/weed/pb/volume_server_pb" "github.com/seaweedfs/seaweedfs/weed/util" @@ -128,7 +130,7 @@ func requestIDUnaryInterceptor() grpc.UnaryServerInterceptor { handler grpc.UnaryHandler, ) (interface{}, error) { incomingMd, _ := metadata.FromIncomingContext(ctx) - idList := incomingMd.Get(util.RequestIDKey) + idList := incomingMd.Get(request_id.AmzRequestIDHeader) var reqID string if len(idList) > 0 { reqID = idList[0] @@ -139,11 +141,12 @@ func requestIDUnaryInterceptor() grpc.UnaryServerInterceptor { ctx = metadata.NewOutgoingContext(ctx, metadata.New(map[string]string{ - util.RequestIDKey: reqID, + request_id.AmzRequestIDHeader: reqID, })) - ctx = util.WithRequestID(ctx, reqID) - grpc.SetTrailer(ctx, metadata.Pairs(util.RequestIDKey, reqID)) + ctx = request_id.Set(ctx, reqID) + + grpc.SetTrailer(ctx, metadata.Pairs(request_id.AmzRequestIDHeader, reqID)) return handler(ctx, req) } diff --git a/weed/server/common.go b/weed/server/common.go index 4041eca51..a5ebd45c8 100644 --- a/weed/server/common.go +++ b/weed/server/common.go @@ -7,9 +7,6 @@ import ( "encoding/json" "errors" "fmt" - "github.com/google/uuid" - "github.com/seaweedfs/seaweedfs/weed/util/version" - "google.golang.org/grpc/metadata" "io" "io/fs" "mime/multipart" @@ -21,18 +18,21 @@ import ( "sync" "time" + "github.com/google/uuid" + "github.com/seaweedfs/seaweedfs/weed/util/request_id" + "github.com/seaweedfs/seaweedfs/weed/util/version" + "google.golang.org/grpc/metadata" + "github.com/seaweedfs/seaweedfs/weed/filer" "github.com/seaweedfs/seaweedfs/weed/s3api/s3_constants" "google.golang.org/grpc" + "github.com/gorilla/mux" "github.com/seaweedfs/seaweedfs/weed/glog" "github.com/seaweedfs/seaweedfs/weed/operation" "github.com/seaweedfs/seaweedfs/weed/stats" "github.com/seaweedfs/seaweedfs/weed/storage/needle" - "github.com/seaweedfs/seaweedfs/weed/util" - - "github.com/gorilla/mux" ) var serverStats *stats.ServerStats @@ -429,18 +429,18 @@ func ProcessRangeRequest(r *http.Request, w http.ResponseWriter, totalSize int64 func requestIDMiddleware(h http.HandlerFunc) http.HandlerFunc { return func(w http.ResponseWriter, r *http.Request) { - reqID := r.Header.Get(util.RequestIdHttpHeader) + reqID := r.Header.Get(request_id.AmzRequestIDHeader) if reqID == "" { reqID = uuid.New().String() } - ctx := context.WithValue(r.Context(), util.RequestIDKey, reqID) + ctx := context.WithValue(r.Context(), request_id.AmzRequestIDHeader, reqID) ctx = metadata.NewOutgoingContext(ctx, metadata.New(map[string]string{ - util.RequestIDKey: reqID, + request_id.AmzRequestIDHeader: reqID, })) - w.Header().Set(util.RequestIdHttpHeader, reqID) + w.Header().Set(request_id.AmzRequestIDHeader, reqID) h(w, r.WithContext(ctx)) } } diff --git a/weed/server/filer_server_handlers_proxy.go b/weed/server/filer_server_handlers_proxy.go index fd22ccd7f..5a0d76a0b 100644 --- a/weed/server/filer_server_handlers_proxy.go +++ b/weed/server/filer_server_handlers_proxy.go @@ -3,9 +3,10 @@ package weed_server import ( "github.com/seaweedfs/seaweedfs/weed/glog" "github.com/seaweedfs/seaweedfs/weed/security" - "github.com/seaweedfs/seaweedfs/weed/util" util_http "github.com/seaweedfs/seaweedfs/weed/util/http" "github.com/seaweedfs/seaweedfs/weed/util/mem" + "github.com/seaweedfs/seaweedfs/weed/util/request_id" + "io" "math/rand/v2" "net/http" @@ -54,7 +55,7 @@ func (fs *FilerServer) proxyToVolumeServer(w http.ResponseWriter, r *http.Reques proxyReq.Header.Set("Host", r.Host) proxyReq.Header.Set("X-Forwarded-For", r.RemoteAddr) - util.ReqWithRequestId(proxyReq, ctx) + request_id.InjectToRequest(ctx, proxyReq) for header, values := range r.Header { for _, value := range values { diff --git a/weed/util/http/http_global_client_util.go b/weed/util/http/http_global_client_util.go index 3cc819a47..5cfd93a2c 100644 --- a/weed/util/http/http_global_client_util.go +++ b/weed/util/http/http_global_client_util.go @@ -6,8 +6,11 @@ import ( "encoding/json" "errors" "fmt" + "github.com/seaweedfs/seaweedfs/weed/util" "github.com/seaweedfs/seaweedfs/weed/util/mem" + "github.com/seaweedfs/seaweedfs/weed/util/request_id" + "io" "net/http" "net/url" @@ -307,7 +310,7 @@ func ReadUrlAsStreamAuthenticated(ctx context.Context, fileUrl, jwt string, ciph } else { req.Header.Add("Range", fmt.Sprintf("bytes=%d-%d", offset, offset+int64(size)-1)) } - util.ReqWithRequestId(req, ctx) + request_id.InjectToRequest(ctx, req) r, err := GetGlobalHttpClient().Do(req) if err != nil { diff --git a/weed/util/request_id.go b/weed/util/request_id.go deleted file mode 100644 index 7945e7cc4..000000000 --- a/weed/util/request_id.go +++ /dev/null @@ -1,27 +0,0 @@ -package util - -import ( - "context" - "net/http" -) - -const ( - RequestIdHttpHeader = "X-Request-ID" - RequestIDKey = "x-request-id" -) - -func GetRequestID(ctx context.Context) string { - if ctx == nil { - return "" - } - id, _ := ctx.Value(RequestIDKey).(string) - return id -} - -func WithRequestID(ctx context.Context, id string) context.Context { - return context.WithValue(ctx, RequestIDKey, id) -} - -func ReqWithRequestId(req *http.Request, ctx context.Context) { - req.Header.Set(RequestIdHttpHeader, GetRequestID(ctx)) -} diff --git a/weed/util/request_id/request_id.go b/weed/util/request_id/request_id.go new file mode 100644 index 000000000..0550cb58b --- /dev/null +++ b/weed/util/request_id/request_id.go @@ -0,0 +1,26 @@ +package request_id + +import ( + "context" + "net/http" +) + +const AmzRequestIDHeader = "x-amz-request-id" + +func Set(ctx context.Context, id string) context.Context { + return context.WithValue(ctx, AmzRequestIDHeader, id) +} + +func Get(ctx context.Context) string { + if ctx == nil { + return "" + } + id, _ := ctx.Value(AmzRequestIDHeader).(string) + return id +} + +func InjectToRequest(ctx context.Context, req *http.Request) { + if req != nil { + req.Header.Set(AmzRequestIDHeader, Get(ctx)) + } +}