authorize: log JWT groups filtering

authorize/evaluator/evaluator.go

@@ -84,10 +84,11 @@ type RequestSession struct {
 
 // Result is the result of evaluation.
 type Result struct {
-	Allow   RuleResult
+	Allow               RuleResult
-	Deny    RuleResult
+	Deny                RuleResult
-	Headers http.Header
+	Headers             http.Header
-	Traces  []contextutil.PolicyEvaluationTrace
+	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,
+		Allow:               policyOutput.Allow,
-		Deny:    policyOutput.Deny,
+		Deny:                policyOutput.Deny,
-		Headers: headersOutput.Headers,
+		Headers:             headersOutput.Headers,
-		Traces:  policyOutput.Traces,
+		Traces:              policyOutput.Traces,
+		AdditionalLogFields: headersOutput.AdditionalLogFields,
 	}
 	return res, nil
 }

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.

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)},
+		response: &HeadersResponse{
-		now:       now,
+			Headers:             make(http.Header),
+			AdditionalLogFields: make(map[log.AuthorizeLogField]any),
+		},
+		now: now,
 	}
 }
 
@@ -337,7 +341,8 @@ func (e *headersEvaluatorEvaluation) getFilteredGroups(ctx context.Context) []st
 	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) {
@@ -345,7 +350,30 @@ func (e *headersEvaluatorEvaluation) getFilteredGroups(ctx context.Context) []st
 			}
 		}
 		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", excluded).
+			Msg("group filtering removed groups")
+		e.response.AdditionalLogFields[log.AuthorizeLogFieldRemovedGroupsCount] = removedCount
+	}
+	return included
 }
 
 // getAllGroups returns the full group names/IDs list (without any filtering).

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)
 
@@ -132,6 +132,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(), "?")
 
@@ -198,6 +199,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:            {},