andwati/zitadel
1
0
Fork 0
mirror of https://github.com/andwati/zitadel.git synced 2026-10-18 05:52:51 +00:00
Code Issues Packages Projects Releases Wiki Activity

feat(telemetry): unify request details (#11509)

Browse Source 
# 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.

<details>

<summary>example output in JSON</summary>

```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
}
```

</details>

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 <[email protected]>
Co-authored-by: muhlemmer <[email protected]>
Co-authored-by: Copilot Autofix powered by AI <[email protected]>
Co-authored-by: Marco A. <[email protected]>
This commit is contained in:
Tim Möhlmann
2026-03-18 14:07:33 +01:00
committed by GitHub
co-authored by Copilot muhlemmer Copilot Autofix powered by AI Marco A.
parent f138082b64
commit 997aa607c4
28 changed files with 765 additions and 79 deletions
Download Patch File Download Diff File Expand all files Collapse all files
backend/v3/instrumentation/instrumentation.go
+2
View File
@@ -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(
backend/v3/instrumentation/request.go
+110
View File
@@ -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
}
backend/v3/instrumentation/request_test.go
+230
View File
@@ -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)
})
}
}
backend/v3/instrumentation/slog.go
+1 -52
View File
@@ -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)
go.mod
+1 -1
View File
@@ -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
go.sum
+2 -2
View File
@@ -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=
internal/api/api.go
+1
View File
@@ -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...),
internal/api/authz/authorization.go
+2
View File
@@ -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 {
internal/api/authz/instance.go
+1 -1
View File
@@ -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)
}
internal/api/grpc/server/connect_middleware/error_interceptor_test.go
-1
View File
@@ -6,7 +6,6 @@ import (
"testing"
"connectrpc.com/connect"
"github.com/stretchr/testify/assert"
"github.com/stretchr/testify/require"
internal/api/grpc/server/connect_middleware/log_interceptor.go
+5 -7
View File
@@ -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
}
internal/api/grpc/server/connect_middleware/request_details_interceptor.go
+36
View File
@@ -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
}
}
}
internal/api/grpc/server/connect_middleware/request_details_interceptor_test.go
+137
View File
@@ -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")
}
internal/api/grpc/server/gateway.go
+1
View File
@@ -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)
internal/api/grpc/server/middleware/cache_interceptor.go
+1 -1
View File
@@ -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
internal/api/grpc/server/middleware/log_interceptor.go
+5 -7
View File
@@ -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
}
internal/api/grpc/server/middleware/request_details_interceptor.go
+29
View File
@@ -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)
}
}
internal/api/grpc/server/middleware/request_details_interceptor_test.go
+65
View File
@@ -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")
})
}
}
internal/api/grpc/server/server.go
+1
View File
@@ -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(),
internal/api/http/header.go
+1
View File
@@ -50,6 +50,7 @@ const (
ReferrerPolicy = "referrer-policy"
FeaturePolicy = "feature-policy"
PermissionsPolicy = "permissions-policy"
XRequestID = "x-request-id"
ZitadelOrgID = "x-zitadel-orgid"
internal/api/http/middleware/log_interceptor.go
+6 -7
View File
@@ -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)),
)
})
}
internal/api/http/middleware/request_details_interceptor.go
+23
View File
@@ -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))
})
}
}
internal/api/http/middleware/request_details_interceptor_test.go
+97
View File
@@ -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")
}
internal/api/oidc/op.go
+2
View File
@@ -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"),
internal/api/saml/provider.go
+2
View File
@@ -70,6 +70,8 @@ func NewProvider(
options := []provider.Option{
provider.WithHttpInterceptors(
middleware.CallDurationHandler,
middleware.RequestDetailsHandler(),
middleware.MetricsHandler(metricTypes),
middleware.TraceHandler(),
middleware.LogHandler("saml"),
internal/api/ui/console/console.go
+1
View File
@@ -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,
internal/api/ui/login/login.go
+2
View File
@@ -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,
internal/api/ui/login/router.go
+1
View File
@@ -4,6 +4,7 @@ import (
"net/http"
"github.com/gorilla/mux"
"github.com/zitadel/zitadel/internal/api/http/middleware"
)