diff --git a/authorize/evaluator/evaluator.go b/authorize/evaluator/evaluator.go index e6316de6c..db140de20 100644 --- a/authorize/evaluator/evaluator.go +++ b/authorize/evaluator/evaluator.go @@ -84,10 +84,11 @@ type RequestSession struct { // Result is the result of evaluation. type Result struct { - Allow RuleResult - Deny RuleResult - Headers http.Header - Traces []contextutil.PolicyEvaluationTrace + Allow RuleResult + Deny RuleResult + Headers http.Header + Traces []contextutil.PolicyEvaluationTrace + AdditionalLogFields map[log.AuthorizeLogField]any } // An Evaluator evaluates policies. @@ -228,10 +229,11 @@ func (e *Evaluator) Evaluate(ctx context.Context, req *Request) (*Result, error) } res := &Result{ - Allow: policyOutput.Allow, - Deny: policyOutput.Deny, - Headers: headersOutput.Headers, - Traces: policyOutput.Traces, + Allow: policyOutput.Allow, + Deny: policyOutput.Deny, + Headers: headersOutput.Headers, + Traces: policyOutput.Traces, + AdditionalLogFields: headersOutput.AdditionalLogFields, } return res, nil } diff --git a/authorize/evaluator/headers_evaluator.go b/authorize/evaluator/headers_evaluator.go index 7ed1baeb6..4eaf32a06 100644 --- a/authorize/evaluator/headers_evaluator.go +++ b/authorize/evaluator/headers_evaluator.go @@ -8,12 +8,14 @@ import ( "github.com/open-policy-agent/opa/rego" "github.com/pomerium/pomerium/authorize/internal/store" + "github.com/pomerium/pomerium/internal/log" "github.com/pomerium/pomerium/internal/telemetry/trace" ) // HeadersResponse is the output from the headers.rego script. type HeadersResponse struct { - Headers http.Header + Headers http.Header + AdditionalLogFields map[log.AuthorizeLogField]any } // A HeadersEvaluator evaluates the headers.rego script. diff --git a/authorize/evaluator/headers_evaluator_evaluation.go b/authorize/evaluator/headers_evaluator_evaluation.go index 82f39151c..ed77bdcbd 100644 --- a/authorize/evaluator/headers_evaluator_evaluation.go +++ b/authorize/evaluator/headers_evaluator_evaluation.go @@ -15,6 +15,7 @@ import ( envoy_config_cluster_v3 "github.com/envoyproxy/go-control-plane/envoy/config/cluster/v3" "github.com/go-jose/go-jose/v3" "github.com/google/uuid" + "github.com/rs/zerolog" "google.golang.org/protobuf/types/known/structpb" "github.com/pomerium/datasource/pkg/directory" @@ -23,7 +24,7 @@ import ( "github.com/pomerium/pomerium/pkg/cryptutil" "github.com/pomerium/pomerium/pkg/grpc/session" "github.com/pomerium/pomerium/pkg/grpc/user" - "github.com/pomerium/pomerium/pkg/slices" + "github.com/pomerium/pomerium/pkg/telemetry/requestid" ) // A headersEvaluatorEvaluation is a single evaluation of the headers evaluator. @@ -57,8 +58,11 @@ func newHeadersEvaluatorEvaluation(evaluator *HeadersEvaluator, request *Request return &headersEvaluatorEvaluation{ evaluator: evaluator, request: request, - response: &HeadersResponse{Headers: make(http.Header)}, - now: now, + response: &HeadersResponse{ + Headers: make(http.Header), + AdditionalLogFields: make(map[log.AuthorizeLogField]any), + }, + now: now, } } @@ -325,7 +329,7 @@ func (e *headersEvaluatorEvaluation) getJWTPayloadGroups(ctx context.Context) [] func (e *headersEvaluatorEvaluation) getGroups(ctx context.Context) []string { groupIDs := e.getGroupIDs(ctx) if len(groupIDs) > 0 { - groupIDs = e.filterGroups(groupIDs) + groupIDs = e.filterGroups(ctx, groupIDs) groups := make([]string, 0, len(groupIDs)*2) groups = append(groups, groupIDs...) groups = append(groups, e.getDataBrokerGroupNames(ctx, groupIDs)...) @@ -337,7 +341,7 @@ func (e *headersEvaluatorEvaluation) getGroups(ctx context.Context) []string { return groups } -func (e *headersEvaluatorEvaluation) filterGroups(groups []string) []string { +func (e *headersEvaluatorEvaluation) filterGroups(ctx context.Context, groups []string) []string { // Apply the global groups filter or the per-route groups filter, if either is enabled. filters := make([]config.JWTGroupsFilter, 0, 2) if f := e.evaluator.store.GetJWTGroupsFilter(); f.Enabled() { @@ -349,7 +353,8 @@ func (e *headersEvaluatorEvaluation) filterGroups(groups []string) []string { if len(filters) == 0 { return groups } - return slices.Filter(groups, func(g string) bool { + + filterFn := func(g string) bool { // A group should be included if it appears in either the global or the route-level filter list. for _, f := range filters { if f.IsAllowed(g) { @@ -357,7 +362,30 @@ func (e *headersEvaluatorEvaluation) filterGroups(groups []string) []string { } } return false - }) + } + var included []string + + // Log the specifics of which groups were filtered out at Debug level. + var excluded *zerolog.Array + if log.Ctx(ctx).GetLevel() <= zerolog.DebugLevel { + excluded = zerolog.Arr() + } + + for _, g := range groups { + if filterFn(g) { + included = append(included, g) + } else if excluded != nil { + excluded.Str(g) + } + } + if removedCount := len(groups) - len(included); removedCount > 0 { + log.Ctx(ctx).Debug(). + Str("request-id", requestid.FromContext(ctx)). + Array("removed-groups-ids", excluded). + Msg("JWT group filtering removed groups") + e.response.AdditionalLogFields[log.AuthorizeLogFieldRemovedGroupsCount] = removedCount + } + return included } func (e *headersEvaluatorEvaluation) getJWTPayloadSID() string { diff --git a/authorize/evaluator/headers_evaluator_test.go b/authorize/evaluator/headers_evaluator_test.go index 470334f2a..04d38bc2d 100644 --- a/authorize/evaluator/headers_evaluator_test.go +++ b/authorize/evaluator/headers_evaluator_test.go @@ -26,6 +26,7 @@ import ( "github.com/pomerium/datasource/pkg/directory" "github.com/pomerium/pomerium/authorize/internal/store" "github.com/pomerium/pomerium/config" + "github.com/pomerium/pomerium/internal/log" "github.com/pomerium/pomerium/pkg/cryptutil" "github.com/pomerium/pomerium/pkg/grpc/databroker" "github.com/pomerium/pomerium/pkg/grpc/session" @@ -503,22 +504,23 @@ func TestHeadersEvaluator_JWTGroupsFilter(t *testing.T) { routeFilter []string sessionID string expected []any + removed int }{ - {"global filter 1", []string{"42", "1"}, nil, "SESSION-1", []any{"1", "42", "GROUP-1", "GROUP-42"}}, - {"global filter 2", []string{"42", "1"}, nil, "SESSION-2", []any{"42", "GROUP-42"}}, - {"route filter 1", nil, []string{"42", "1"}, "SESSION-1", []any{"1", "42", "GROUP-1", "GROUP-42"}}, - {"route filter 2", nil, []string{"42", "1"}, "SESSION-2", []any{"42", "GROUP-42"}}, - {"both filters 1", []string{"1"}, []string{"42"}, "SESSION-1", []any{"1", "42", "GROUP-1", "GROUP-42"}}, - {"both filters 2", []string{"1"}, []string{"42"}, "SESSION-2", []any{"42", "GROUP-42"}}, - {"cannot filter by name", []string{"GROUP-1"}, nil, "SESSION-1", []any{}}, - {"overlapping", []string{"1"}, []string{"1"}, "SESSION-1", []any{"1", "GROUP-1"}}, - {"empty route filter", []string{"1", "2", "3"}, []string{}, "SESSION-1", []any{"1", "2", "3", "GROUP-1", "GROUP-2", "GROUP-3"}}, + {"global filter 1", []string{"42", "1"}, nil, "SESSION-1", []any{"1", "42", "GROUP-1", "GROUP-42"}, 48}, + {"global filter 2", []string{"42", "1"}, nil, "SESSION-2", []any{"42", "GROUP-42"}, 24}, + {"route filter 1", nil, []string{"42", "1"}, "SESSION-1", []any{"1", "42", "GROUP-1", "GROUP-42"}, 48}, + {"route filter 2", nil, []string{"42", "1"}, "SESSION-2", []any{"42", "GROUP-42"}, 24}, + {"both filters 1", []string{"1"}, []string{"42"}, "SESSION-1", []any{"1", "42", "GROUP-1", "GROUP-42"}, 48}, + {"both filters 2", []string{"1"}, []string{"42"}, "SESSION-2", []any{"42", "GROUP-42"}, 24}, + {"cannot filter by name", []string{"GROUP-1"}, nil, "SESSION-1", []any{}, 50}, + {"overlapping", []string{"1"}, []string{"1"}, "SESSION-1", []any{"1", "GROUP-1"}, 49}, + {"empty route filter", []string{"1", "2", "3"}, []string{}, "SESSION-1", []any{"1", "2", "3", "GROUP-1", "GROUP-2", "GROUP-3"}, 47}, { "no filtering", nil, nil, "SESSION-10", - []any{"10", "20", "30", "40", "50", "GROUP-10", "GROUP-20", "GROUP-30", "GROUP-40", "GROUP-50"}, + []any{"10", "20", "30", "40", "50", "GROUP-10", "GROUP-20", "GROUP-30", "GROUP-40", "GROUP-50"}, 0, }, // filtering has no effect on groups from an IdP "groups" claim - {"groups claim", []string{"foo", "quux"}, nil, "SESSION-11", []any{"foo", "bar", "baz"}}, + {"groups claim", []string{"foo", "quux"}, nil, "SESSION-11", []any{"foo", "bar", "baz"}, 0}, } ctx := storage.WithQuerier(context.Background(), storage.NewStaticQuerier(records...)) @@ -538,6 +540,11 @@ func TestHeadersEvaluator_JWTGroupsFilter(t *testing.T) { require.NoError(t, err) decoded := decodeJWTAssertion(t, resp.Headers) assert.Equal(t, c.expected, decoded["groups"]) + if c.removed > 0 { + assert.Equal(t, c.removed, resp.AdditionalLogFields[log.AuthorizeLogFieldRemovedGroupsCount]) + } else { + assert.Nil(t, resp.AdditionalLogFields[log.AuthorizeLogFieldRemovedGroupsCount]) + } }) } } diff --git a/authorize/log.go b/authorize/log.go index 3e5088262..3f1a571ec 100644 --- a/authorize/log.go +++ b/authorize/log.go @@ -33,7 +33,7 @@ func (a *Authorize) logAuthorizeCheck( evt := log.Ctx(ctx).Info().Str("service", "authorize") fields := a.currentOptions.Load().GetAuthorizeLogFields() for _, field := range fields { - evt = populateLogEvent(ctx, field, evt, in, s, u, hdrs, impersonateDetails) + evt = populateLogEvent(ctx, field, evt, in, s, u, hdrs, impersonateDetails, res) } evt = log.HTTPHeaders(evt, fields, hdrs) @@ -139,6 +139,7 @@ func populateLogEvent( u *user.User, hdrs map[string]string, impersonateDetails *impersonateDetails, + res *evaluator.Result, ) *zerolog.Event { path, query, _ := strings.Cut(in.GetAttributes().GetRequest().GetHttp().GetPath(), "?") @@ -205,6 +206,11 @@ func populateLogEvent( } return evt.Str(string(field), userID) default: + if res != nil { + if v, ok := res.AdditionalLogFields[field]; ok { + evt = evt.Interface(string(field), v) + } + } return evt } } diff --git a/authorize/log_test.go b/authorize/log_test.go index e03c1da70..9c2ad8453 100644 --- a/authorize/log_test.go +++ b/authorize/log_test.go @@ -11,6 +11,7 @@ import ( "github.com/rs/zerolog" "github.com/stretchr/testify/assert" + "github.com/pomerium/pomerium/authorize/evaluator" "github.com/pomerium/pomerium/internal/log" "github.com/pomerium/pomerium/pkg/grpc/session" "github.com/pomerium/pomerium/pkg/grpc/user" @@ -64,6 +65,11 @@ func Test_populateLogEvent(t *testing.T) { sessionID: "IMPERSONATE-SESSION-ID", userID: "IMPERSONATE-USER-ID", } + res := &evaluator.Result{ + AdditionalLogFields: map[log.AuthorizeLogField]any{ + log.AuthorizeLogFieldRemovedGroupsCount: 42, + }, + } for _, tc := range []struct { field log.AuthorizeLogField @@ -82,6 +88,7 @@ func Test_populateLogEvent(t *testing.T) { {log.AuthorizeLogFieldMethod, s, `{"method":"GET"}`}, {log.AuthorizeLogFieldPath, s, `{"path":"https://www.example.com/some/path"}`}, {log.AuthorizeLogFieldQuery, s, `{"query":"a=b"}`}, + {log.AuthorizeLogFieldRemovedGroupsCount, s, `{"removed-groups-count":42}`}, {log.AuthorizeLogFieldRequestID, s, `{"request-id":"REQUEST-ID"}`}, {log.AuthorizeLogFieldServiceAccountID, sa, `{"service-account-id":"SERVICE-ACCOUNT-ID"}`}, {log.AuthorizeLogFieldSessionID, s, `{"session-id":"SESSION-ID"}`}, @@ -97,7 +104,7 @@ func Test_populateLogEvent(t *testing.T) { var buf bytes.Buffer log := zerolog.New(&buf) evt := log.Log() - evt = populateLogEvent(ctx, tc.field, evt, checkRequest, tc.s, u, headers, impersonateDetails) + evt = populateLogEvent(ctx, tc.field, evt, checkRequest, tc.s, u, headers, impersonateDetails, res) evt.Send() assert.Equal(t, tc.expect, strings.TrimSpace(buf.String())) diff --git a/internal/log/authorize.go b/internal/log/authorize.go index 18521797e..f2f0c07e2 100644 --- a/internal/log/authorize.go +++ b/internal/log/authorize.go @@ -23,6 +23,7 @@ const ( AuthorizeLogFieldMethod AuthorizeLogField = "method" AuthorizeLogFieldPath AuthorizeLogField = "path" AuthorizeLogFieldQuery AuthorizeLogField = "query" + AuthorizeLogFieldRemovedGroupsCount AuthorizeLogField = "removed-groups-count" AuthorizeLogFieldRequestID AuthorizeLogField = "request-id" AuthorizeLogFieldServiceAccountID AuthorizeLogField = "service-account-id" AuthorizeLogFieldSessionID AuthorizeLogField = "session-id" @@ -41,6 +42,7 @@ var DefaultAuthorizeLogFields = []AuthorizeLogField{ AuthorizeLogFieldImpersonateSessionID, AuthorizeLogFieldImpersonateUserID, AuthorizeLogFieldImpersonateEmail, + AuthorizeLogFieldRemovedGroupsCount, AuthorizeLogFieldServiceAccountID, AuthorizeLogFieldUser, AuthorizeLogFieldEmail, @@ -63,6 +65,7 @@ var authorizeLogFieldLookup = map[AuthorizeLogField]struct{}{ AuthorizeLogFieldMethod: {}, AuthorizeLogFieldPath: {}, AuthorizeLogFieldQuery: {}, + AuthorizeLogFieldRemovedGroupsCount: {}, AuthorizeLogFieldRequestID: {}, AuthorizeLogFieldServiceAccountID: {}, AuthorizeLogFieldSessionID: {},