Context-based logging with request ID (#6899)

8 files changed, 302 insertions, 48 deletions

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))
+	}
+}