From 2bde1daab5ff713cf8c4edafa3a875455ffc62b2 Mon Sep 17 00:00:00 2001 From: Kenneth Jenkins <51246568+kenjenkins@users.noreply.github.com> Date: Wed, 8 Jan 2025 13:33:21 -0800 Subject: [PATCH] authorize: log JWT groups filtering Add a new Authorize Log Fields option for logging the number of groups removed during JWT groups filtering. This will be enabled by default. Additionally, when the log level is Debug (or more verbose), store and log the IDs of any groups removed during JWT groups filtering. --- authorize/evaluator/evaluator.go | 18 ++++---- authorize/evaluator/headers_evaluator.go | 4 +- .../evaluator/headers_evaluator_evaluation.go | 42 +++++++++++++++---- authorize/evaluator/headers_evaluator_test.go | 29 ++++++++----- authorize/log.go | 8 +++- authorize/log_test.go | 9 +++- internal/log/authorize.go | 3 ++ 7 files changed, 84 insertions(+), 29 deletions(-) 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: {},