authorize: log JWT groups filtering (#5432) (#5454)

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

@@ -88,6 +88,7 @@ type Result struct {
 	Deny                RuleResult
 	Headers             http.Header
 	Traces              []contextutil.PolicyEvaluationTrace
+	AdditionalLogFields map[log.AuthorizeLogField]any
 }
 
 // An Evaluator evaluates policies.
@@ -232,6 +233,7 @@ func (e *Evaluator) Evaluate(ctx context.Context, req *Request) (*Result, error)
 		Deny:                policyOutput.Deny,
 		Headers:             headersOutput.Headers,
 		Traces:              policyOutput.Traces,
+		AdditionalLogFields: headersOutput.AdditionalLogFields,
 	}
 	return res, nil
 }

authorize/evaluator/headers_evaluator.go

@@ -11,6 +11,7 @@ import (
 
 	"github.com/pomerium/pomerium/authorize/internal/store"
 	"github.com/pomerium/pomerium/config"
+	"github.com/pomerium/pomerium/internal/log"
 	"github.com/pomerium/pomerium/internal/telemetry/trace"
 )
 
@@ -67,6 +68,7 @@ func NewHeadersRequestFromPolicy(policy *config.Policy, http RequestHTTP) (*Head
 // HeadersResponse is the output from the headers.rego script.
 type HeadersResponse struct {
 	Headers             http.Header
+	AdditionalLogFields map[log.AuthorizeLogField]any
 }
 
 // A HeadersEvaluator evaluates the headers.rego script.

authorize/evaluator/headers_evaluator_evaluation.go

@@ -14,6 +14,7 @@ import (
 
 	"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"
@@ -22,7 +23,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.
@@ -56,7 +57,10 @@ func newHeadersEvaluatorEvaluation(evaluator *HeadersEvaluator, request *Headers
 	return &headersEvaluatorEvaluation{
 		evaluator: evaluator,
 		request:   request,
-		response:  &HeadersResponse{Headers: make(http.Header)},
+		response: &HeadersResponse{
+			Headers:             make(http.Header),
+			AdditionalLogFields: make(map[log.AuthorizeLogField]any),
+		},
 		now: now,
 	}
 }
@@ -285,7 +289,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)...)
@@ -297,7 +301,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() {
@@ -309,7 +313,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) {
@@ -317,7 +322,31 @@ 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-group-ids", excluded).
+			Strs("remaining-group-ids", included).
+			Msg("JWT group filtering removed groups")
+		e.response.AdditionalLogFields[log.AuthorizeLogFieldRemovedGroupsCount] = removedCount
+	}
+	return included
 }
 
 func (e *headersEvaluatorEvaluation) getJWTPayloadSID() string {

authorize/evaluator/headers_evaluator_test.go

@@ -25,6 +25,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"
@@ -564,22 +565,24 @@ 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 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"}},
+		{"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"}},
+		{"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"}},
+		{"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"}},
+		{"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"}},
+		{"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{}},
+		{"cannot filter by name", []string{"GROUP-1"}, nil, "SESSION-1", []any{}, 50},
-		{"overlapping", []string{"1"}, []string{"1"}, "SESSION-1", []any{"1", "GROUP-1"}},
+		{"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"}},
+		{"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"},
+			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...))
@@ -597,6 +600,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])
+			}
 		})
 	}
 }

authorize/log.go

@@ -34,7 +34,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)
 
@@ -152,6 +152,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(), "?")
 
@@ -218,6 +219,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
 	}
 }

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()))

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:            {},