diff --git a/backend/v3/instrumentation/instrumentation.go b/backend/v3/instrumentation/instrumentation.go index cecad1918..d83dbfbfb 100644 --- a/backend/v3/instrumentation/instrumentation.go +++ b/backend/v3/instrumentation/instrumentation.go @@ -68,6 +68,8 @@ func NewMeter(name string, options ...metric.MeterOption) *Meter { } } +// RequestFilter returns an [otelhttp.Filter] that excludes requests +// with paths starting with any of the specified prefixes. func RequestFilter(ignoredPrefix ...string) otelhttp.Filter { return func(r *http.Request) bool { return !slices.ContainsFunc( diff --git a/backend/v3/instrumentation/request.go b/backend/v3/instrumentation/request.go new file mode 100644 index 000000000..c6f9d97a3 --- /dev/null +++ b/backend/v3/instrumentation/request.go @@ -0,0 +1,110 @@ +package instrumentation + +import ( + "context" + "log/slog" + "sync" + "time" + + "github.com/rs/xid" + + "github.com/zitadel/zitadel/internal/api/call" +) + +// allow injection for testing +var xidWithTime = xid.NewWithTime + +// WithRequestDetails creates a new context with request details, including a unique request ID. +// The request ID is generated using the call timestamp as returned by [call.FromContext]. +// +// Note: The returned context carries a mutable pointer to requestDetails. +// This allows subsequent calls to SetInstanceID/SetUserID to update the details +// visible to the logger, even if the logger holds the original context created here. +func WithRequestDetails(ctx context.Context, instanceHost, publicHost string) context.Context { + details := &requestDetails{ + id: xidWithTime(call.FromContext(ctx)), + instanceHost: instanceHost, + publicHost: publicHost, + } + return context.WithValue(ctx, ctxKey{}, details) +} + +func getRequestDetails(ctx context.Context) (*requestDetails, bool) { + details, ok := ctx.Value(ctxKey{}).(*requestDetails) + return details, ok +} + +// SetInstanceID sets the instance ID in the request details stored in the context. +// It uses a mutex to update the shared state safely, ensuring upstream loggers see the change. +func SetInstanceID(ctx context.Context, instanceID string) { + if details, ok := getRequestDetails(ctx); ok { + details.mtx.Lock() + details.instanceID = instanceID + details.mtx.Unlock() + } +} + +// SetUserID sets the user ID in the request details stored in the context. +// It uses a mutex to update the shared state safely, ensuring upstream loggers see the change. +func SetUserID(ctx context.Context, userID string) { + if details, ok := getRequestDetails(ctx); ok { + details.mtx.Lock() + details.userID = userID + details.mtx.Unlock() + } +} + +// GetRequestID retrieves the request ID from the context. +// [xid.NilID] is returned if no request details are found in the context. +func GetRequestID(ctx context.Context) xid.ID { + d, ok := getRequestDetails(ctx) + if !ok { + return xid.NilID() + } + d.mtx.Lock() + defer d.mtx.Unlock() + return d.id +} + +type ctxKey struct{} + +type requestDetails struct { + mtx sync.Mutex + id xid.ID + instanceHost string + publicHost string // may optionally be set through header (login v2) + instanceID string + userID string +} + +func (d *requestDetails) slogAttributes() []any { + attributes := make([]any, 0, 5) + + d.mtx.Lock() + defer d.mtx.Unlock() + + attributes = append(attributes, + slog.String("id", d.id.String()), + slog.String("instance_host", d.instanceHost), + ) + if d.publicHost != "" { + attributes = append(attributes, slog.String("public_host", d.publicHost)) + } + if d.instanceID != "" { + attributes = append(attributes, slog.String("instance_id", d.instanceID)) + } + if d.userID != "" { + attributes = append(attributes, slog.String("user_id", d.userID)) + } + + return attributes +} + +func requestDetailsExtractor(ctx context.Context, _ time.Time, _ slog.Level, _ string) []slog.Attr { + if d, ok := getRequestDetails(ctx); ok { + return []slog.Attr{ + slog.Group("request", d.slogAttributes()...), + } + } + return nil +} diff --git a/backend/v3/instrumentation/request_test.go b/backend/v3/instrumentation/request_test.go new file mode 100644 index 000000000..19628dfa0 --- /dev/null +++ b/backend/v3/instrumentation/request_test.go @@ -0,0 +1,230 @@ +package instrumentation + +import ( + "context" + "log/slog" + "testing" + "time" + + "github.com/rs/xid" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +var testID = xid.New() + +func TestSetInstanceID(t *testing.T) { + originalXidWithTime := xidWithTime + xidWithTime = func(time.Time) xid.ID { + return testID + } + t.Cleanup(func() { + xidWithTime = originalXidWithTime + }) + + tests := []struct { + name string + ctx context.Context + instanceID string + wantDetails *requestDetails + }{ + { + name: "no request details in context", + ctx: context.Background(), + wantDetails: nil, + }, + { + name: "request details in context", + ctx: WithRequestDetails(context.Background(), "instanceHost", "publicHost"), + instanceID: "instanceID", + wantDetails: &requestDetails{ + id: testID, + instanceID: "instanceID", + instanceHost: "instanceHost", + publicHost: "publicHost", + userID: "", + }, + }, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + SetInstanceID(tt.ctx, tt.instanceID) + got, ok := getRequestDetails(tt.ctx) + require.Equal(t, tt.wantDetails != nil, ok) + assert.Equal(t, tt.wantDetails, got) + }) + } +} + +func TestSetUserID(t *testing.T) { + originalXidWithTime := xidWithTime + xidWithTime = func(time.Time) xid.ID { + return testID + } + t.Cleanup(func() { + xidWithTime = originalXidWithTime + }) + + tests := []struct { + name string + ctx context.Context + userID string + wantDetails *requestDetails + }{ + { + name: "no request details in context", + ctx: context.Background(), + wantDetails: nil, + }, + { + name: "request details in context", + ctx: WithRequestDetails(context.Background(), "instanceHost", "publicHost"), + userID: "userID", + wantDetails: &requestDetails{ + id: testID, + instanceHost: "instanceHost", + publicHost: "publicHost", + userID: "userID", + }, + }, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + SetUserID(tt.ctx, tt.userID) + got, ok := getRequestDetails(tt.ctx) + require.Equal(t, tt.wantDetails != nil, ok) + assert.Equal(t, tt.wantDetails, got) + }) + } +} + +func TestGetRequestID(t *testing.T) { + originalXidWithTime := xidWithTime + xidWithTime = func(time.Time) xid.ID { + return testID + } + t.Cleanup(func() { + xidWithTime = originalXidWithTime + }) + + reqCtx := WithRequestDetails(context.Background(), "instanceHost", "publicHost") + tests := []struct { + name string + ctx context.Context + wantID xid.ID + }{ + { + name: "no request ID in context", + ctx: context.Background(), + wantID: xid.NilID(), + }, + { + name: "request ID in context", + ctx: reqCtx, + wantID: testID, + }, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + got := GetRequestID(tt.ctx) + assert.Equal(t, tt.wantID, got) + }) + } +} + +func Test_requestDetails_slogAttributes(t *testing.T) { + type fields struct { + id xid.ID + instanceHost string + publicHost string + instanceID string + userID string + } + tests := []struct { + name string + fields fields + want []any + }{ + { + name: "all fields set", + fields: fields{ + id: testID, + instanceHost: "instanceHost", + publicHost: "publicHost", + instanceID: "instanceID", + userID: "userID", + }, + want: []any{ + slog.String("id", testID.String()), + slog.String("instance_host", "instanceHost"), + slog.String("public_host", "publicHost"), + slog.String("instance_id", "instanceID"), + slog.String("user_id", "userID"), + }, + }, + { + name: "only required fields set", + fields: fields{ + id: testID, + instanceHost: "instanceHost", + publicHost: "publicHost", + }, + want: []any{ + slog.String("id", testID.String()), + slog.String("instance_host", "instanceHost"), + slog.String("public_host", "publicHost"), + }, + }, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + d := &requestDetails{ + id: tt.fields.id, + instanceHost: tt.fields.instanceHost, + publicHost: tt.fields.publicHost, + instanceID: tt.fields.instanceID, + userID: tt.fields.userID, + } + got := d.slogAttributes() + assert.Equal(t, tt.want, got) + }) + } +} + +func Test_requestDetailsExtractor(t *testing.T) { + originalXidWithTime := xidWithTime + xidWithTime = func(time.Time) xid.ID { + return testID + } + t.Cleanup(func() { + xidWithTime = originalXidWithTime + }) + tests := []struct { + name string + ctx context.Context + want []slog.Attr + }{ + { + name: "no request details in context", + ctx: context.Background(), + want: nil, + }, + { + name: "request details in context", + ctx: WithRequestDetails(context.Background(), "instanceHost", "publicHost"), + want: []slog.Attr{ + slog.Group("request", + slog.String("id", testID.String()), + slog.String("instance_host", "instanceHost"), + slog.String("public_host", "publicHost"), + ), + }, + }, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + got := requestDetailsExtractor(tt.ctx, time.Time{}, 0, "") + assert.Equal(t, tt.want, got) + }) + } +} diff --git a/backend/v3/instrumentation/slog.go b/backend/v3/instrumentation/slog.go index 51c73123e..93f856eee 100644 --- a/backend/v3/instrumentation/slog.go +++ b/backend/v3/instrumentation/slog.go @@ -9,7 +9,6 @@ import ( "sync/atomic" "time" - "github.com/rs/xid" slogmulti "github.com/samber/slog-multi" slogctx "github.com/veqryn/slog-context" slogotel "github.com/veqryn/slog-context/otel" @@ -158,9 +157,8 @@ func setLogger(provider *log.LoggerProvider, cfg LogConfig) { stdErrHandler, &slogctx.HandlerOptions{ Prependers: []slogctx.AttrExtractor{ - instanceExtractor, - requestIDExtractor, causeExtractor, + requestDetailsExtractor, slogotel.ExtractTraceSpanID, slogctx.ExtractPrepended, }, @@ -177,55 +175,6 @@ func setLogger(provider *log.LoggerProvider, cfg LogConfig) { slog.SetDefault(logger) } -const ( - ProtocolHttp = "http" - ProtocolConnect = "connect" - ProtocolGrpc = "grpc" -) - -// Instance is a minimal interface for logging the instance ID. -type Instance interface { - InstanceID() string -} - -// SetInstance adds the instance to the context for logging. -func SetInstance(ctx context.Context, instance Instance) context.Context { - return context.WithValue(ctx, ctxKeyInstance, instance) -} - -// SetRequest generates a new [xid.ID] based on the passed request timestamp -// and adds it to the context. -func SetRequestID(ctx context.Context, ts time.Time) context.Context { - return context.WithValue(ctx, ctxKeyRequestID, xid.NewWithTime(ts)) -} - -type ctxKeyType int - -const ( - ctxKeyRequestID ctxKeyType = iota - ctxKeyInstance -) - -// instanceExtractor sets the instance ID from [Instance] to a log entry. -func instanceExtractor(ctx context.Context, _ time.Time, _ slog.Level, _ string) []slog.Attr { - if instance, ok := ctx.Value(ctxKeyInstance).(Instance); ok { - return []slog.Attr{ - slog.String("instance", instance.InstanceID()), - } - } - return nil -} - -// requestIDExtractor sets the request XID to a log entry. -func requestIDExtractor(ctx context.Context, _ time.Time, _ slog.Level, _ string) []slog.Attr { - if r, ok := ctx.Value(ctxKeyRequestID).(xid.ID); ok { - return []slog.Attr{ - slog.String("request_id", r.String()), - } - } - return nil -} - // causeExtractor sets the cause of a canceled context to a log entry. func causeExtractor(ctx context.Context, _ time.Time, _ slog.Level, _ string) []slog.Attr { err := context.Cause(ctx) diff --git a/go.mod b/go.mod index 77a54a3f0..f48115ecb 100644 --- a/go.mod +++ b/go.mod @@ -102,7 +102,7 @@ require ( github.com/zitadel/passwap v0.10.0 github.com/zitadel/saml v0.4.1 github.com/zitadel/schema v1.3.1 - github.com/zitadel/sloggcp v0.5.1 + github.com/zitadel/sloggcp v0.6.0 go.opentelemetry.io/contrib/bridges/otelslog v0.13.0 go.opentelemetry.io/contrib/instrumentation/google.golang.org/grpc/otelgrpc v0.63.0 go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp v0.63.0 diff --git a/go.sum b/go.sum index e83684c65..fc05ec079 100644 --- a/go.sum +++ b/go.sum @@ -842,8 +842,8 @@ github.com/zitadel/saml v0.4.1 h1:4PPOAvnUFcfwOFIAFZ3oGTMD+tKVeF96ySfGBf5j3IU= github.com/zitadel/saml v0.4.1/go.mod h1:ybs3e4tIWdYgSYBpuCsvf3T4FNDfbXYM+GPv5vIpHYk= github.com/zitadel/schema v1.3.1 h1:QT3kwiRIRXXLVAs6gCK/u044WmUVh6IlbLXUsn6yRQU= github.com/zitadel/schema v1.3.1/go.mod h1:071u7D2LQacy1HAN+YnMd/mx1qVE2isb0Mjeqg46xnU= -github.com/zitadel/sloggcp v0.5.1 h1:AoUN9+6iRZCAy0P+iR7TOpvCO+lOpUzGslvzKSoAKKc= -github.com/zitadel/sloggcp v0.5.1/go.mod h1:QNiYB+IkVRsx/NT/Z2rnBevp9D4F/5o8DAGrUO0BBoo= +github.com/zitadel/sloggcp v0.6.0 h1:8Xx8Se4Mnm5UhVCSA24SkECIe1qLeE7U82WBLqyZVaw= +github.com/zitadel/sloggcp v0.6.0/go.mod h1:QNiYB+IkVRsx/NT/Z2rnBevp9D4F/5o8DAGrUO0BBoo= go.etcd.io/bbolt v1.3.3/go.mod h1:IbVyRI1SCnLcuJnV2u8VeU0CEYM7e686BmAb1XKL+uU= go.etcd.io/etcd v0.0.0-20191023171146-3cf2f69b5738/go.mod h1:dnLIgRNXwCJa5e+c6mIZCrds/GIG4ncV9HhK5PX7jPg= go.opencensus.io v0.20.1/go.mod h1:6WKK9ahsWS3RSO+PY9ZHZUfv2irvY6gN279GOPZjmmk= diff --git a/internal/api/api.go b/internal/api/api.go index 4d135b43b..f322ad3f7 100644 --- a/internal/api/api.go +++ b/internal/api/api.go @@ -212,6 +212,7 @@ func (a *API) RegisterService(ctx context.Context, srv server.Server) error { func (a *API) registerConnectServer(service server.ConnectServer) { prefix, handler := service.RegisterConnectServer( connect_middleware.CallDurationHandler(), + connect_middleware.RequestDetailsHandler(), a.connectOTELInterceptor, connect_middleware.MetricsHandler(metricTypes, grpc_api.Probes...), connect_middleware.LogHandler(grpc_api.Probes...), diff --git a/internal/api/authz/authorization.go b/internal/api/authz/authorization.go index 25130584a..697889192 100644 --- a/internal/api/authz/authorization.go +++ b/internal/api/authz/authorization.go @@ -7,6 +7,7 @@ import ( "slices" "strings" + "github.com/zitadel/zitadel/backend/v3/instrumentation" "github.com/zitadel/zitadel/internal/telemetry/tracing" "github.com/zitadel/zitadel/internal/zerrors" ) @@ -28,6 +29,7 @@ func CheckUserAuthorization(ctx context.Context, req interface{}, token, orgID, if err != nil { return nil, err } + instrumentation.SetUserID(ctx, ctxData.UserID) if requiredAuthOption.Permission == authenticated { return func(parent context.Context) context.Context { diff --git a/internal/api/authz/instance.go b/internal/api/authz/instance.go index 9829ce2eb..fe6c46b89 100644 --- a/internal/api/authz/instance.go +++ b/internal/api/authz/instance.go @@ -117,7 +117,7 @@ func GetFeatures(ctx context.Context) feature.Features { } func WithInstance(ctx context.Context, instance Instance) context.Context { - ctx = instrumentation.SetInstance(ctx, instance) + instrumentation.SetInstanceID(ctx, instance.InstanceID()) return context.WithValue(ctx, instanceKey, instance) } diff --git a/internal/api/grpc/server/connect_middleware/error_interceptor_test.go b/internal/api/grpc/server/connect_middleware/error_interceptor_test.go index 28a8b259e..b98dea72a 100644 --- a/internal/api/grpc/server/connect_middleware/error_interceptor_test.go +++ b/internal/api/grpc/server/connect_middleware/error_interceptor_test.go @@ -6,7 +6,6 @@ import ( "testing" "connectrpc.com/connect" - "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" diff --git a/internal/api/grpc/server/connect_middleware/log_interceptor.go b/internal/api/grpc/server/connect_middleware/log_interceptor.go index a3d33d529..05a5cd3a1 100644 --- a/internal/api/grpc/server/connect_middleware/log_interceptor.go +++ b/internal/api/grpc/server/connect_middleware/log_interceptor.go @@ -5,15 +5,16 @@ import ( "log/slog" "slices" "strings" - "time" "connectrpc.com/connect" - "github.com/zitadel/zitadel/backend/v3/instrumentation" "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" - http_util "github.com/zitadel/zitadel/internal/api/http" + "github.com/zitadel/zitadel/internal/api/call" ) +// LogHandler is a connect interceptor that logs the request details +// including protocol, domain, service, HTTP method, path, response code, and duration. +// It depends on [CallDurationHandler] and [RequestDetailsHandler] to set the request start time and ID in the context. func LogHandler(ignoredMethodSuffixes ...string) connect.UnaryInterceptorFunc { return func(next connect.UnaryFunc) connect.UnaryFunc { return func(ctx context.Context, req connect.AnyRequest) (connect.AnyResponse, error) { @@ -22,9 +23,7 @@ func LogHandler(ignoredMethodSuffixes ...string) connect.UnaryInterceptorFunc { }) { return next(ctx, req) } - start := time.Now() ctx = logging.NewCtx(ctx, logging.StreamRequest) - ctx = instrumentation.SetRequestID(ctx, start) resp, err := next(ctx, req) var code connect.Code @@ -34,12 +33,11 @@ func LogHandler(ignoredMethodSuffixes ...string) connect.UnaryInterceptorFunc { spec := req.Spec() logging.Info(ctx, "request served", slog.String("protocol", "connect"), - slog.Any("domain", http_util.DomainContext(ctx)), slog.String("service", serviceFromRPCMethod(spec.Procedure)), slog.String("http_method", req.HTTPMethod()), slog.String("path", spec.Procedure), slog.Any("code", code), - slog.Duration("duration", time.Since(start)), + slog.Duration("duration", call.Took(ctx)), ) return resp, err } diff --git a/internal/api/grpc/server/connect_middleware/request_details_interceptor.go b/internal/api/grpc/server/connect_middleware/request_details_interceptor.go new file mode 100644 index 000000000..044c1f182 --- /dev/null +++ b/internal/api/grpc/server/connect_middleware/request_details_interceptor.go @@ -0,0 +1,36 @@ +package connect_middleware + +import ( + "context" + "errors" + + "connectrpc.com/connect" + + "github.com/zitadel/zitadel/backend/v3/instrumentation" + http_util "github.com/zitadel/zitadel/internal/api/http" +) + +// RequestDetailsHandler is a connect interceptor that sets request details in the context +// and adds the ID to the response headers. +// It depends on [CallDurationHandler] to set the request start time in the context. +func RequestDetailsHandler() connect.UnaryInterceptorFunc { + return func(next connect.UnaryFunc) connect.UnaryFunc { + return func(ctx context.Context, req connect.AnyRequest) (connect.AnyResponse, error) { + domainCtx := http_util.DomainContext(ctx) + reqCtx := instrumentation.WithRequestDetails(ctx, domainCtx.InstanceHost, domainCtx.PublicHost) + id := instrumentation.GetRequestID(reqCtx) + + resp, err := next(reqCtx, req) + if resp != nil { + resp.Header().Set(http_util.XRequestID, id.String()) + } + + var target *connect.Error + if errors.As(err, &target) { + // adds the request ID to the error response trailer + target.Meta().Set(http_util.XRequestID, id.String()) + } + return resp, err + } + } +} diff --git a/internal/api/grpc/server/connect_middleware/request_details_interceptor_test.go b/internal/api/grpc/server/connect_middleware/request_details_interceptor_test.go new file mode 100644 index 000000000..2d577699b --- /dev/null +++ b/internal/api/grpc/server/connect_middleware/request_details_interceptor_test.go @@ -0,0 +1,137 @@ +package connect_middleware + +import ( + "context" + "net/http" + "testing" + + "connectrpc.com/connect" + "github.com/rs/xid" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + + "github.com/zitadel/zitadel/backend/v3/instrumentation" + "github.com/zitadel/zitadel/internal/api/call" + http_util "github.com/zitadel/zitadel/internal/api/http" + "github.com/zitadel/zitadel/internal/zerrors" +) + +func TestRequestDetailsHandler_Connect(t *testing.T) { + tests := []struct { + name string + setupContext bool + hasError bool + wantErr bool + }{ + { + name: "sets request ID header on success", + setupContext: true, + hasError: false, + wantErr: false, + }, + { + name: "sets request ID trailer on error", + setupContext: true, + hasError: true, + wantErr: true, + }, + { + name: "sets request ID header without call context", + setupContext: false, + hasError: false, + wantErr: false, + }, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + ctx := context.Background() + + // Setup context with call duration if needed + if tt.setupContext { + ctx = call.WithTimestamp(ctx) + } + + // Create test request + req := &mockReq[struct{}]{ + procedure: "/test", + header: http.Header{}, + } + + // Create a mock handler + var capturedID string + handler := func(ctx context.Context, req connect.AnyRequest) (connect.AnyResponse, error) { + id := instrumentation.GetRequestID(ctx) + require.False(t, id.IsNil(), "Request ID should be present in context") + capturedID = id.String() + + if tt.hasError { + return nil, connect.NewError(connect.CodeInternal, zerrors.ThrowInternal(nil, "TEST", "test error")) + } + + resp := &connect.Response[struct{}]{} + return resp, nil + } + + interceptor := RequestDetailsHandler() + unaryFunc := interceptor(handler) + resp, err := unaryFunc(ctx, req) + + if tt.wantErr { + require.Error(t, err) + + // Verify request ID is in error metadata (trailer) + var connectErr *connect.Error + if assert.ErrorAs(t, err, &connectErr) { + requestID := connectErr.Meta().Get(http_util.XRequestID) + require.NotEmpty(t, requestID, "Request ID should be set in error metadata") + _, err := xid.FromString(requestID) + require.NoError(t, err, "Request ID in error metadata should be a valid xid") + assert.Equal(t, capturedID, requestID, "Request ID in context should match error metadata") + } + } else { + require.NoError(t, err) + require.NotNil(t, resp) + + // Verify request ID is set in response header + requestID := resp.Header().Get(http_util.XRequestID) + require.NotEmpty(t, requestID, "Request ID should be set in response header") + _, err := xid.FromString(requestID) + require.NoError(t, err, "Request ID in response header should be a valid xid") + assert.Equal(t, capturedID, requestID, "Request ID in context should match header") + } + + // Verify request ID is set in context + require.NotEmpty(t, capturedID, "Request ID should be set in context") + }) + } +} + +func TestRequestDetailsHandler_Connect_Stability(t *testing.T) { + // Test that the same request gets consistent request ID + ctx := call.WithTimestamp(context.Background()) + req := &mockReq[struct{}]{ + procedure: "/test", + header: http.Header{}, + } + + var capturedID string + handler := func(ctx context.Context, req connect.AnyRequest) (connect.AnyResponse, error) { + id := instrumentation.GetRequestID(ctx) + require.False(t, id.IsNil(), "Request ID should be present in context") + capturedID = id.String() + resp := &connect.Response[struct{}]{} + return resp, nil + } + + interceptor := RequestDetailsHandler() + unaryFunc := interceptor(handler) + resp, err := unaryFunc(ctx, req) + + require.NoError(t, err) + require.NotNil(t, resp) + + headerID := resp.Header().Get(http_util.XRequestID) + + // Verify the ID in context matches the ID in header + assert.Equal(t, capturedID, headerID, "Request ID in context should match header") +} diff --git a/internal/api/grpc/server/gateway.go b/internal/api/grpc/server/gateway.go index 5fa344ec1..83be0d927 100644 --- a/internal/api/grpc/server/gateway.go +++ b/internal/api/grpc/server/gateway.go @@ -207,6 +207,7 @@ func addInterceptors( accessInterceptor *http_mw.AccessInterceptor, ) http.Handler { handler = http_mw.CallDurationHandler(handler) + handler = http_mw.RequestDetailsHandler()(handler) handler = http_mw.CORSInterceptor(handler) handler = http_mw.RobotsTagHandler(handler) handler = http_mw.DefaultTraceHandler(handler) diff --git a/internal/api/grpc/server/middleware/cache_interceptor.go b/internal/api/grpc/server/middleware/cache_interceptor.go index 0b2447d4d..bea487a1f 100644 --- a/internal/api/grpc/server/middleware/cache_interceptor.go +++ b/internal/api/grpc/server/middleware/cache_interceptor.go @@ -24,7 +24,7 @@ func NoCacheInterceptor() grpc.UnaryServerInterceptor { for key, value := range headers { header.Append(runtime.MetadataHeaderPrefix+key, value) } - err := grpc.SendHeader(ctx, header) + err := grpc.SetHeader(ctx, header) logging.Log("MIDDLE-efh41").OnError(err).WithField("req", info.FullMethod).Warn("cannot send cache-control on grpc response") resp, err := handler(ctx, req) return resp, err diff --git a/internal/api/grpc/server/middleware/log_interceptor.go b/internal/api/grpc/server/middleware/log_interceptor.go index ee5bedab1..9873ef0ba 100644 --- a/internal/api/grpc/server/middleware/log_interceptor.go +++ b/internal/api/grpc/server/middleware/log_interceptor.go @@ -6,17 +6,18 @@ import ( "net/http" "slices" "strings" - "time" "google.golang.org/grpc" "google.golang.org/grpc/codes" "google.golang.org/grpc/status" - "github.com/zitadel/zitadel/backend/v3/instrumentation" "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" - http_util "github.com/zitadel/zitadel/internal/api/http" + "github.com/zitadel/zitadel/internal/api/call" ) +// LogHandler is a gRPC interceptor that logs the request details +// including protocol, domain, service, HTTP method, path, response code, and duration. +// It depends on [CallDurationHandler] and [RequestDetailsHandler] to set the request start time and ID in the context. func LogHandler(ignoredMethodSuffixes ...string) grpc.UnaryServerInterceptor { return func(ctx context.Context, req any, info *grpc.UnaryServerInfo, next grpc.UnaryHandler) (any, error) { if slices.ContainsFunc(ignoredMethodSuffixes, func(s string) bool { @@ -24,9 +25,7 @@ func LogHandler(ignoredMethodSuffixes ...string) grpc.UnaryServerInterceptor { }) { return next(ctx, req) } - start := time.Now() ctx = logging.NewCtx(ctx, logging.StreamRequest) - ctx = instrumentation.SetRequestID(ctx, start) resp, err := next(ctx, req) var code codes.Code @@ -35,12 +34,11 @@ func LogHandler(ignoredMethodSuffixes ...string) grpc.UnaryServerInterceptor { } logging.Info(ctx, "request served", slog.String("protocol", "grpc"), - slog.Any("domain", http_util.DomainContext(ctx)), slog.String("service", serviceFromRPCMethod(info.FullMethod)), slog.String("http_method", http.MethodPost), // gRPC always uses POST slog.String("path", info.FullMethod), slog.Any("code", code), - slog.Duration("duration", time.Since(start)), + slog.Duration("duration", call.Took(ctx)), ) return resp, err } diff --git a/internal/api/grpc/server/middleware/request_details_interceptor.go b/internal/api/grpc/server/middleware/request_details_interceptor.go new file mode 100644 index 000000000..641bf86aa --- /dev/null +++ b/internal/api/grpc/server/middleware/request_details_interceptor.go @@ -0,0 +1,29 @@ +package middleware + +import ( + "context" + + "google.golang.org/grpc" + "google.golang.org/grpc/metadata" + + "github.com/zitadel/zitadel/backend/v3/instrumentation" + "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" + http_util "github.com/zitadel/zitadel/internal/api/http" +) + +// RequestDetailsHandler is a gRPC interceptor that sets a request ID in the context +// and adds the ID to the response headers. +// It depends on [CallDurationHandler] to set the request start time in the context. +func RequestDetailsHandler() grpc.UnaryServerInterceptor { + return func(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (interface{}, error) { + domainCtx := http_util.DomainContext(ctx) + reqCtx := instrumentation.WithRequestDetails(ctx, domainCtx.InstanceHost, domainCtx.PublicHost) + id := instrumentation.GetRequestID(reqCtx) + md := metadata.New(map[string]string{http_util.XRequestID: id.String()}) + + err := grpc.SetHeader(reqCtx, md) + logging.OnError(reqCtx, err).Warn("cannot set request ID to response header") + + return handler(reqCtx, req) + } +} diff --git a/internal/api/grpc/server/middleware/request_details_interceptor_test.go b/internal/api/grpc/server/middleware/request_details_interceptor_test.go new file mode 100644 index 000000000..f3db1088e --- /dev/null +++ b/internal/api/grpc/server/middleware/request_details_interceptor_test.go @@ -0,0 +1,65 @@ +package middleware + +import ( + "context" + "testing" + + "github.com/stretchr/testify/require" + "google.golang.org/grpc" + + "github.com/zitadel/zitadel/backend/v3/instrumentation" + "github.com/zitadel/zitadel/internal/api/call" +) + +func TestRequestDetailsHandler_gRPC(t *testing.T) { + tests := []struct { + name string + setupContext bool + handler grpc.UnaryHandler + wantErr bool + }{ + { + name: "sets request ID header on success", + setupContext: true, + handler: emptyMockHandler, + wantErr: false, + }, + { + name: "sets request ID header on error", + setupContext: true, + handler: errorMockHandler, + wantErr: true, + }, + { + name: "sets request ID header without call context", + setupContext: false, + handler: emptyMockHandler, + wantErr: false, + }, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + ctx := context.Background() + + // Setup context with call duration if needed + if tt.setupContext { + ctx = call.WithTimestamp(ctx) + } + + // Create a handler that captures the request ID from context + var capturedID string + handler := func(ctx context.Context, req interface{}) (interface{}, error) { + id := instrumentation.GetRequestID(ctx) + require.False(t, id.IsNil(), "Request ID should be present in context") + capturedID = id.String() + return tt.handler(ctx, req) + } + + interceptor := RequestDetailsHandler() + _, err := interceptor(ctx, &mockReq{}, mockInfo("/test"), handler) + require.Equalf(t, tt.wantErr, err != nil, "Expected error: %v, got: %v", tt.wantErr, err) + // Verify request ID is set in context + require.NotEmpty(t, capturedID, "Request ID should be set in context") + }) + } +} diff --git a/internal/api/grpc/server/server.go b/internal/api/grpc/server/server.go index ef61a5fe2..5d6b4f317 100644 --- a/internal/api/grpc/server/server.go +++ b/internal/api/grpc/server/server.go @@ -72,6 +72,7 @@ func CreateServer( grpc.UnaryInterceptor( grpc_middleware.ChainUnaryServer( middleware.CallDurationHandler(), + middleware.RequestDetailsHandler(), middleware.MetricsHandler(metricTypes, grpc_api.Probes...), middleware.LogHandler(grpc_api.Probes...), middleware.NoCacheInterceptor(), diff --git a/internal/api/http/header.go b/internal/api/http/header.go index eec261666..1408cfa47 100644 --- a/internal/api/http/header.go +++ b/internal/api/http/header.go @@ -50,6 +50,7 @@ const ( ReferrerPolicy = "referrer-policy" FeaturePolicy = "feature-policy" PermissionsPolicy = "permissions-policy" + XRequestID = "x-request-id" ZitadelOrgID = "x-zitadel-orgid" diff --git a/internal/api/http/middleware/log_interceptor.go b/internal/api/http/middleware/log_interceptor.go index c81ee01c8..9846d57ac 100644 --- a/internal/api/http/middleware/log_interceptor.go +++ b/internal/api/http/middleware/log_interceptor.go @@ -3,13 +3,15 @@ package middleware import ( "log/slog" "net/http" - "time" "github.com/zitadel/zitadel/backend/v3/instrumentation" "github.com/zitadel/zitadel/backend/v3/instrumentation/logging" - http_util "github.com/zitadel/zitadel/internal/api/http" + "github.com/zitadel/zitadel/internal/api/call" ) +// LogHandler is an HTTP middleware that logs the request details +// including protocol, domain, service, HTTP method, path, response code, and duration. +// It depends on [CallDurationHandler] and [RequestDetailsHandler] to set the request start time and ID in the context. func LogHandler(service string, ignoredPrefix ...string) func(http.Handler) http.Handler { return func(next http.Handler) http.Handler { filter := instrumentation.RequestFilter(ignoredPrefix...) @@ -18,21 +20,18 @@ func LogHandler(service string, ignoredPrefix ...string) func(http.Handler) http next.ServeHTTP(w, r) return } - start := time.Now() ctx := logging.NewCtx(r.Context(), logging.StreamRequest) - ctx = instrumentation.SetRequestID(ctx, start) sw := newStatusWriter(w) next.ServeHTTP(sw, r.WithContext(ctx)) logging.Info(ctx, "request served", slog.String("protocol", "http"), - slog.Any("domain", http_util.DomainContext(ctx)), slog.String("service", service), - slog.String("http_method", r.Method), // gRPC always uses POST + slog.String("http_method", r.Method), slog.String("path", r.URL.Path), slog.Int("status", sw.status), - slog.Duration("duration", time.Since(start)), + slog.Duration("duration", call.Took(ctx)), ) }) } diff --git a/internal/api/http/middleware/request_details_interceptor.go b/internal/api/http/middleware/request_details_interceptor.go new file mode 100644 index 000000000..51c6b493e --- /dev/null +++ b/internal/api/http/middleware/request_details_interceptor.go @@ -0,0 +1,23 @@ +package middleware + +import ( + "net/http" + + "github.com/zitadel/zitadel/backend/v3/instrumentation" + http_util "github.com/zitadel/zitadel/internal/api/http" +) + +// RequestDetailsHandler is a HTTP middleware that sets a request ID in the context +// and adds the ID to the response headers. +// It depends on [CallDurationHandler] to set the request start time in the context. +func RequestDetailsHandler() func(http.Handler) http.Handler { + return func(next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + domainCtx := http_util.DomainContext(r.Context()) + ctx := instrumentation.WithRequestDetails(r.Context(), domainCtx.InstanceHost, domainCtx.PublicHost) + id := instrumentation.GetRequestID(ctx) + w.Header().Set(http_util.XRequestID, id.String()) + next.ServeHTTP(w, r.WithContext(ctx)) + }) + } +} diff --git a/internal/api/http/middleware/request_details_interceptor_test.go b/internal/api/http/middleware/request_details_interceptor_test.go new file mode 100644 index 000000000..5e7d9a42a --- /dev/null +++ b/internal/api/http/middleware/request_details_interceptor_test.go @@ -0,0 +1,97 @@ +package middleware + +import ( + "net/http" + "net/http/httptest" + "testing" + + "github.com/rs/xid" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + + "github.com/zitadel/zitadel/backend/v3/instrumentation" + "github.com/zitadel/zitadel/internal/api/call" + http_util "github.com/zitadel/zitadel/internal/api/http" +) + +func TestRequestDetailsHandler(t *testing.T) { + tests := []struct { + name string + setupContext bool + status int + }{ + { + name: "sets request ID header on success", + setupContext: true, + status: http.StatusOK, + }, + { + name: "sets request ID header on error", + setupContext: true, + status: http.StatusInternalServerError, + }, + { + name: "sets request ID header without call context", + setupContext: false, + status: http.StatusOK, + }, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + // Create test request + req := httptest.NewRequest(http.MethodGet, "/test", nil) + + // Setup context with call duration if needed + if tt.setupContext { + req = req.WithContext(call.WithTimestamp(req.Context())) + } + + rec := httptest.NewRecorder() + + // Create test handler that returns the specified status + handler := RequestDetailsHandler()(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + // Verify request ID is in context + requestID := instrumentation.GetRequestID(r.Context()) + assert.False(t, requestID.IsNil(), "Request ID should be present in context") + + w.WriteHeader(tt.status) + })) + + handler.ServeHTTP(rec, req) + + // Verify response + resp := rec.Result() + assert.Equal(t, tt.status, resp.StatusCode) + + // Verify x-request-id header is set + requestID := resp.Header.Get(http_util.XRequestID) + require.NotEmpty(t, requestID, "x-request-id header should be set") + + // Verify the x-request-id header is a valid xid format + _, err := xid.FromString(requestID) + require.NoError(t, err, "x-request-id header should be a valid xid") + }) + } +} + +func TestRequestDetailsHandler_Stability(t *testing.T) { + // Test that the same request gets consistent request ID + req := httptest.NewRequest(http.MethodGet, "/test", nil) + req = req.WithContext(call.WithTimestamp(req.Context())) + rec := httptest.NewRecorder() + + var capturedID string + handler := RequestDetailsHandler()(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + id := instrumentation.GetRequestID(r.Context()) + require.False(t, id.IsNil(), "Request ID should be present in context") + capturedID = id.String() + })) + + handler.ServeHTTP(rec, req) + + resp := rec.Result() + headerID := resp.Header.Get(http_util.XRequestID) + + // Verify the ID in context matches the ID in header + assert.Equal(t, capturedID, headerID, "Request ID in context should match header") +} diff --git a/internal/api/oidc/op.go b/internal/api/oidc/op.go index 35576774c..022204de3 100644 --- a/internal/api/oidc/op.go +++ b/internal/api/oidc/op.go @@ -183,6 +183,8 @@ func NewServer( server.authorizeCallbackHandler, op.WithFallbackLogger(fallbackLogger), op.WithHTTPMiddleware( + middleware.CallDurationHandler, + middleware.RequestDetailsHandler(), middleware.MetricsHandler(metricTypes), middleware.TraceHandler(), middleware.LogHandler("oidc"), diff --git a/internal/api/saml/provider.go b/internal/api/saml/provider.go index b95739451..4fe93d3b3 100644 --- a/internal/api/saml/provider.go +++ b/internal/api/saml/provider.go @@ -70,6 +70,8 @@ func NewProvider( options := []provider.Option{ provider.WithHttpInterceptors( + middleware.CallDurationHandler, + middleware.RequestDetailsHandler(), middleware.MetricsHandler(metricTypes), middleware.TraceHandler(), middleware.LogHandler("saml"), diff --git a/internal/api/ui/console/console.go b/internal/api/ui/console/console.go index 774c6e089..cb19f970e 100644 --- a/internal/api/ui/console/console.go +++ b/internal/api/ui/console/console.go @@ -116,6 +116,7 @@ func Start(config Config, externalSecure bool, issuer op.IssuerFromRequest, call env := handler.NewRoute().Path(envRequestPath).Subrouter() env.Use( callDurationInterceptor, + middleware.RequestDetailsHandler(), middleware.TraceHandler(), middleware.LogHandler("console"), instanceHandler, diff --git a/internal/api/ui/login/login.go b/internal/api/ui/login/login.go index a573e6fcb..ea60527ac 100644 --- a/internal/api/ui/login/login.go +++ b/internal/api/ui/login/login.go @@ -216,6 +216,8 @@ func CreateLogin( security := middleware.SecurityHeaders(csp(), login.cspErrorHandler) login.router = CreateRouter(login, + middleware.CallDurationHandler, + middleware.RequestDetailsHandler(), middleware.TraceHandler(IgnoreInstanceEndpoints...), middleware.LogHandler("login_v1", IgnoreInstanceEndpoints...), oidcInstanceHandler, diff --git a/internal/api/ui/login/router.go b/internal/api/ui/login/router.go index 6f8ab5537..e2a9b8f1b 100644 --- a/internal/api/ui/login/router.go +++ b/internal/api/ui/login/router.go @@ -4,6 +4,7 @@ import ( "net/http" "github.com/gorilla/mux" + "github.com/zitadel/zitadel/internal/api/http/middleware" )