From 997aa607c474f5d09a84f425cd11620ec7c356cd Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tim=20M=C3=B6hlmann?= Date: Wed, 18 Mar 2026 14:07:33 +0100 Subject: [PATCH] feat(telemetry): unify request details (#11509) # Which Problems Are Solved In the "new" structured logging, request details were added in different middlewares, such as request, instance and user IDs. This meant the the upstream request logging middleware did not have access to metadata that got added later, resulting in incomplete logs. Furthermore it was not possible to correlate an API error response to log output. # How the Problems Are Solved A mutable request details object is added to the context early on. When the api authz function run, the instance and user IDs are added to this object as they become available. Every logline emitted after this (time-wise) will then all contain these details under the `request` log group.
example output in JSON ```json { "time": "2026-03-13T19:21:20.890428806Z", "level": "INFO", "source": { "function": "github.com/zitadel/zitadel/internal/api/grpc/server/connect_middleware.LogHandler.func1.1", "file": "/workspaces/zitadel/internal/api/grpc/server/connect_middleware/log_interceptor.go", "line": 34 }, "msg": "request served", "request": { "id": "d6q67c04vtjmi77cbbpg", "instance_host": "localhost:8080", "instance_id": "362349751439458307", "user_id": "362349751440048131" }, "TraceID": "a9e0fee3522224f3583bbdcda737f4b4", "SpanID": "a563056eee36920a", "stream": "request", "version": "2026-03-13T19:20:59Z", "protocol": "connect", "service": "zitadel.user.v2.UserService", "http_method": "POST", "path": "/zitadel.user.v2.UserService/ListUsers", "code": "code_0", "duration": 12254350 } ```
Request IDs are now also returned with a response header or metadata. Depending on the protocol: - HTTP calls always return the request ID as header, regardless of status - gRPC calls always return the request ID as header, even if there was an error - connect RPC calls returns the request ID as header on success, trailer in case of error. This is because header must be set on the response object, which is nil in case of error. When there is an error, metadata can be added which are then sent as trailers. # Additional Changes - Use the existing call duration middleware for both request ID and logging for a consistent request start timestamp in all layers. - Upgrade sloggcp for some fixes (notably TraceID) - Modify the NoCache middleware so it uses `SetHeaders` instead of `SendHeaders`. The latter prevented any other handler from setting headers, including the new request ID middleware. # Additional Context Follow up on demo of: - https://github.com/zitadel/zitadel/pull/11159 - https://github.com/zitadel/zitadel/pull/11435 - backport to v4 --------- Co-authored-by: Copilot <198982749+Copilot@users.noreply.github.com> Co-authored-by: muhlemmer <5411563+muhlemmer@users.noreply.github.com> Co-authored-by: Copilot Autofix powered by AI <175728472+Copilot@users.noreply.github.com> Co-authored-by: Marco A. --- backend/v3/instrumentation/instrumentation.go | 2 + backend/v3/instrumentation/request.go | 110 +++++++++ backend/v3/instrumentation/request_test.go | 230 ++++++++++++++++++ backend/v3/instrumentation/slog.go | 53 +--- go.mod | 2 +- go.sum | 4 +- internal/api/api.go | 1 + internal/api/authz/authorization.go | 2 + internal/api/authz/instance.go | 2 +- .../error_interceptor_test.go | 1 - .../connect_middleware/log_interceptor.go | 12 +- .../request_details_interceptor.go | 36 +++ .../request_details_interceptor_test.go | 137 +++++++++++ internal/api/grpc/server/gateway.go | 1 + .../server/middleware/cache_interceptor.go | 2 +- .../grpc/server/middleware/log_interceptor.go | 12 +- .../middleware/request_details_interceptor.go | 29 +++ .../request_details_interceptor_test.go | 65 +++++ internal/api/grpc/server/server.go | 1 + internal/api/http/header.go | 1 + .../api/http/middleware/log_interceptor.go | 13 +- .../middleware/request_details_interceptor.go | 23 ++ .../request_details_interceptor_test.go | 97 ++++++++ internal/api/oidc/op.go | 2 + internal/api/saml/provider.go | 2 + internal/api/ui/console/console.go | 1 + internal/api/ui/login/login.go | 2 + internal/api/ui/login/router.go | 1 + 28 files changed, 765 insertions(+), 79 deletions(-) create mode 100644 backend/v3/instrumentation/request.go create mode 100644 backend/v3/instrumentation/request_test.go create mode 100644 internal/api/grpc/server/connect_middleware/request_details_interceptor.go create mode 100644 internal/api/grpc/server/connect_middleware/request_details_interceptor_test.go create mode 100644 internal/api/grpc/server/middleware/request_details_interceptor.go create mode 100644 internal/api/grpc/server/middleware/request_details_interceptor_test.go create mode 100644 internal/api/http/middleware/request_details_interceptor.go create mode 100644 internal/api/http/middleware/request_details_interceptor_test.go 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" )