diff --git a/main.go b/main.go index 6169dd1d..6f17bc0f 100644 --- a/main.go +++ b/main.go @@ -133,6 +133,8 @@ type authServerOptions struct { maxHttpRequestBodySize int64 kubeClientQPS float32 kubeClientBurst int + enableLoggingFields bool + loggingFieldsMaxValueBytes int addSensitiveFields []string removeSensitiveFields []string addSensitiveHeaders []string @@ -201,6 +203,8 @@ func authServerCmd(opts *authServerOptions) *cobra.Command { cmd.PersistentFlags().StringVar(&opts.oidcTLSMaxVersion, "oidc-tls-max-version", utils.EnvVar("OIDC_TLS_MAX_VERSION", ""), "Maximum TLS version for the OIDC Discovery server (1.0, 1.1, 1.2, 1.3)") cmd.PersistentFlags().StringSliceVar(&opts.oidcTLSCipherSuites, "oidc-tls-cipher-suites", utils.EnvVarStringSlice("OIDC_TLS_CIPHER_SUITES", ","), "Comma-separated list of TLS cipher suites (IANA names) for the OIDC Discovery server") cmd.PersistentFlags().IntVar(&opts.evaluatorCacheSize, "evaluator-cache-size", utils.EnvVar("EVALUATOR_CACHE_SIZE", 1), "Cache size of each Authorino evaluator if enabled in the AuthConfig - in megabytes") + cmd.PersistentFlags().BoolVar(&opts.enableLoggingFields, "enable-logging-fields", utils.EnvVar("ENABLE_LOGGING_FIELDS", false), "Enable configurable logging fields from filter metadata in authorization decision logs") + cmd.PersistentFlags().IntVar(&opts.loggingFieldsMaxValueBytes, "logging-fields-max-value-bytes", utils.EnvVar("LOGGING_FIELDS_MAX_VALUE_BYTES", 1024), "Maximum length in bytes for logging field values; 0 disables truncation") cmd.PersistentFlags().BoolVar(&opts.deepMetricsEnabled, "deep-metrics-enabled", utils.EnvVar("DEEP_METRICS_ENABLED", false), "Enable deep metrics at the level of each evaluator when requested in the AuthConfig, exported by the metrics server") cmd.PersistentFlags().IntVar(&opts.webhookServicePort, "webhook-service-port", 9443, "Port number of the webhook server") cmd.PersistentFlags().BoolVar(&opts.enableLeaderElection, "enable-leader-election", false, "Enable leader election for status updater - ensures only one instance of Authorino tries to update the status of reconciled resources") @@ -529,7 +533,7 @@ func startExtAuthServerGRPC(authConfigIndex index.Index, opts authServerOptions) grpcServer := grpc.NewServer(grpcServerOpts...) reflection.Register(grpcServer) - envoy_auth.RegisterAuthorizationServer(grpcServer, &service.AuthService{Index: authConfigIndex, Timeout: timeoutMs(opts.timeout)}) + envoy_auth.RegisterAuthorizationServer(grpcServer, &service.AuthService{Index: authConfigIndex, Timeout: timeoutMs(opts.timeout), EnableLoggingFields: opts.enableLoggingFields, LoggingFieldsMaxValueBytes: opts.loggingFieldsMaxValueBytes}) healthpb.RegisterHealthServer(grpcServer, &service.HealthService{}) grpc_prometheus.Register(grpcServer) grpc_prometheus.EnableHandlingTimeHistogram() @@ -545,7 +549,7 @@ func startExtAuthServerGRPC(authConfigIndex index.Index, opts authServerOptions) } func startExtAuthServerHTTP(authConfigIndex index.Index, opts authServerOptions) { - startHTTPService("auth", opts.extAuthHTTPPort, service.HTTPAuthorizationBasePath, opts.tlsCertPath, opts.tlsCertKeyPath, opts.tlsMinVersion, opts.tlsMaxVersion, opts.tlsCipherSuites, service.NewAuthService(authConfigIndex, timeoutMs(opts.timeout), opts.maxHttpRequestBodySize)) + startHTTPService("auth", opts.extAuthHTTPPort, service.HTTPAuthorizationBasePath, opts.tlsCertPath, opts.tlsCertKeyPath, opts.tlsMinVersion, opts.tlsMaxVersion, opts.tlsCipherSuites, service.NewAuthService(authConfigIndex, timeoutMs(opts.timeout), opts.maxHttpRequestBodySize, opts.enableLoggingFields, opts.loggingFieldsMaxValueBytes)) } func startOIDCServer(authConfigIndex index.Index, opts authServerOptions) { diff --git a/pkg/service/auth.go b/pkg/service/auth.go index 77f52c65..8429ee18 100644 --- a/pkg/service/auth.go +++ b/pkg/service/auth.go @@ -73,13 +73,15 @@ func init() { // AuthService is the server API for the authorization service. type AuthService struct { - Index index.Index - Timeout time.Duration - MaxHttpRequestBodySize int64 + Index index.Index + Timeout time.Duration + MaxHttpRequestBodySize int64 + EnableLoggingFields bool + LoggingFieldsMaxValueBytes int } -func NewAuthService(index index.Index, timeout time.Duration, maxHttpRequestBodySize int64) *AuthService { - return &AuthService{Index: index, Timeout: timeout, MaxHttpRequestBodySize: maxHttpRequestBodySize} +func NewAuthService(index index.Index, timeout time.Duration, maxHttpRequestBodySize int64, enableLoggingFields bool, loggingFieldsMaxValueBytes int) *AuthService { + return &AuthService{Index: index, Timeout: timeout, MaxHttpRequestBodySize: maxHttpRequestBodySize, EnableLoggingFields: enableLoggingFields, LoggingFieldsMaxValueBytes: loggingFieldsMaxValueBytes} } // ServeHTTP invokes authorization check for a simple GET/POST HTTP authorization request @@ -284,13 +286,13 @@ func (a *AuthService) Check(parentContext gocontext.Context, req *envoy_auth.Che // If we couldn't find the AuthConfig in the config, we return and deny. if authConfig == nil { result := auth.AuthResult{Code: rpc.NOT_FOUND, Message: RESPONSE_MESSAGE_SERVICE_NOT_FOUND} - a.logAuthResult(result, ctx) + a.logAuthResult(result, ctx, nil) return a.deniedResponse(result), nil } if err := context.CheckContext(ctx); err != nil { result := auth.AuthResult{Code: rpc.UNAVAILABLE} - a.logAuthResult(result, ctx) + a.logAuthResult(result, ctx, nil) context.Cancel(ctx) span.RecordError(err) span.SetStatus(otel_codes.Error, err.Error()) @@ -308,7 +310,13 @@ func (a *AuthService) Check(parentContext gocontext.Context, req *envoy_auth.Che span.SetStatus(otel_codes.Error, err.Error()) } - a.logAuthResult(result, ctx) + var loggingFields map[string]string + if a.EnableLoggingFields { + if p, ok := pipeline.(*AuthPipeline); ok { + loggingFields = p.loggingFields(a.LoggingFieldsMaxValueBytes) + } + } + a.logAuthResult(result, ctx, loggingFields) if result.Success() { return a.successResponse(result, ctx), nil @@ -401,7 +409,7 @@ func (a *AuthService) logAuthRequest(req *envoy_auth.CheckRequest, ctx gocontext } } -func (a *AuthService) logAuthResult(result auth.AuthResult, ctx gocontext.Context) { +func (a *AuthService) logAuthResult(result auth.AuthResult, ctx gocontext.Context, loggingFields map[string]string) { logger := log.FromContext(ctx) success := result.Success() baseLogData := []interface{}{"authorized", success, "response", result.Code.String()} @@ -415,12 +423,18 @@ func (a *AuthService) logAuthResult(result auth.AuthResult, ctx gocontext.Contex } logData = append(logData, "object", reducedResult) } + for k, v := range loggingFields { + logData = append(logData, k, v) + } logger.Info("outgoing authorization response", logData...) // info if logger.V(1).Enabled() { if !success { baseLogData = append(baseLogData, "object", result) } + for k, v := range loggingFields { + baseLogData = append(baseLogData, k, v) + } logger.V(1).Info("outgoing authorization response", baseLogData...) // debug } } diff --git a/pkg/service/auth_pipeline.go b/pkg/service/auth_pipeline.go index 3e2f2b30..913e7597 100644 --- a/pkg/service/auth_pipeline.go +++ b/pkg/service/auth_pipeline.go @@ -556,6 +556,58 @@ func (pipeline *AuthPipeline) metricLabels() map[string]string { return labels } +const loggingFieldPrefix = "logging." + +func truncateValue(s string, maxLen int) string { + if maxLen > 0 && len(s) > maxLen { + return s[:maxLen] + "...(truncated)" + } + return s +} + +func (pipeline *AuthPipeline) loggingFields(maxValueBytes int) map[string]string { + fields := make(map[string]string) + + filteredMetadata := pipeline.GetRequest().GetAttributes().GetMetadataContext().GetFilterMetadata() + if customFields, ok := filteredMetadata["io.kuadrant.logging.fields"]; ok { + for k, v := range customFields.Fields { + key := loggingFieldPrefix + k + switch kind := v.Kind.(type) { + case *structpb.Value_StringValue: + fields[key] = truncateValue(kind.StringValue, maxValueBytes) + + case *structpb.Value_NumberValue: + fields[key] = fmt.Sprintf("%v", kind.NumberValue) + + case *structpb.Value_BoolValue: + fields[key] = fmt.Sprintf("%v", kind.BoolValue) + + case *structpb.Value_StructValue: + if celExprField, ok := kind.StructValue.Fields["cel_expr"]; ok { + if exprStr := celExprField.GetStringValue(); exprStr != "" { + expr, err := cel.NewExpression(exprStr) + if err != nil { + pipeline.Logger.Error(err, "failed to parse CEL expression", "expression", exprStr) + continue + } + value, err := expr.ResolveFor(pipeline.GetAuthorizationJSON()) + if err != nil { + pipeline.Logger.Error(err, "failed to evaluate CEL expression", "expression", exprStr) + continue + } + fields[key] = truncateValue(fmt.Sprintf("%v", value), maxValueBytes) + } + } + + default: + pipeline.Logger.V(1).Info("unexpected value kind", "kind", kind) + } + } + } + + return fields +} + func (pipeline *AuthPipeline) GetRequest() *envoy_auth.CheckRequest { return pipeline.Request } diff --git a/pkg/service/auth_pipeline_test.go b/pkg/service/auth_pipeline_test.go index c37b50cb..3daa9773 100644 --- a/pkg/service/auth_pipeline_test.go +++ b/pkg/service/auth_pipeline_test.go @@ -703,3 +703,190 @@ func TestPipelineMetricLabels(t *testing.T) { assert.Equal(t, "", labels["unResolvableLabel"]) assert.Equal(t, "", labels["nullLabel"]) } + +func TestPipelineLoggingFields(t *testing.T) { + reqJSON := `{ + "attributes": { + "metadata_context": { + "filter_metadata": { + "io.kuadrant.logging.fields": { + "client_identity": { "cel_expr": "request.host" }, + "request_method": { "cel_expr": "request.method" }, + "static_field": "audit-v1", + "numeric_field": 42, + "bool_field": true, + "unresolvable": { "cel_expr": "auth.nonexistent.value" }, + "null_field": null + } + } + }, + "request": { + "http": { + "host": "my-api", + "path": "/v1/chat/completions", + "method": "POST", + "headers": { + "authorization": "Bearer token123" + } + } + } + } + }` + + var request envoy_auth.CheckRequest + _ = gojson.Unmarshal([]byte(reqJSON), &request) + + pipeline := newTestAuthPipeline( + evaluators.AuthConfig{}, + &request, + ) + + fields := pipeline.loggingFields(1024) + + assert.Equal(t, 5, len(fields)) + + assert.Equal(t, "my-api", fields["logging.client_identity"]) + assert.Equal(t, "POST", fields["logging.request_method"]) + assert.Equal(t, "audit-v1", fields["logging.static_field"]) + assert.Equal(t, "42", fields["logging.numeric_field"]) + assert.Equal(t, "true", fields["logging.bool_field"]) + assert.Equal(t, "", fields["logging.unresolvable"]) + assert.Equal(t, "", fields["logging.null_field"]) +} + +func TestPipelineLoggingFieldsEmpty(t *testing.T) { + var request envoy_auth.CheckRequest + _ = gojson.Unmarshal([]byte(rawRequest), &request) + + pipeline := newTestAuthPipeline( + evaluators.AuthConfig{}, + &request, + ) + + fields := pipeline.loggingFields(1024) + + assert.Equal(t, 0, len(fields)) +} + +func TestLoggingFieldsResolvesIdentityOnAllow(t *testing.T) { + reqJSON := `{ + "attributes": { + "metadata_context": { + "filter_metadata": { + "io.kuadrant.logging.fields": { + "identity_anonymous": { "cel_expr": "auth.identity.anonymous" }, + "req_method": { "cel_expr": "request.method" } + } + } + }, + "request": { + "http": { + "host": "my-api", + "path": "/v1/chat/completions", + "method": "POST" + } + } + } + }` + + var request envoy_auth.CheckRequest + _ = gojson.Unmarshal([]byte(reqJSON), &request) + + authCred := auth.NewAuthCredential("", "") + pipeline := newTestAuthPipeline(evaluators.AuthConfig{ + IdentityConfigs: []auth.AuthConfigEvaluator{ + &evaluators.IdentityConfig{Name: "anonymous", Noop: &identity.Noop{AuthCredentials: authCred}}, + }, + }, &request) + + result := pipeline.Evaluate() + assert.Equal(t, result.Code, rpc.OK) + + fields := pipeline.loggingFields(1024) + + assert.Equal(t, "true", fields["logging.identity_anonymous"]) + assert.Equal(t, "POST", fields["logging.req_method"]) +} + +func TestLoggingFieldsResolvesIdentityOnAuthzDeny(t *testing.T) { + reqJSON := `{ + "attributes": { + "metadata_context": { + "filter_metadata": { + "io.kuadrant.logging.fields": { + "identity_anonymous": { "cel_expr": "auth.identity.anonymous" }, + "req_method": { "cel_expr": "request.method" } + } + } + }, + "request": { + "http": { + "host": "my-api", + "path": "/v1/chat/completions", + "method": "POST" + } + } + } + }` + + var request envoy_auth.CheckRequest + _ = gojson.Unmarshal([]byte(reqJSON), &request) + + authCred := auth.NewAuthCredential("", "") + pipeline := newTestAuthPipeline(evaluators.AuthConfig{ + IdentityConfigs: []auth.AuthConfigEvaluator{ + &evaluators.IdentityConfig{Name: "anonymous", Noop: &identity.Noop{AuthCredentials: authCred}}, + }, + AuthorizationConfigs: []auth.AuthConfigEvaluator{ + &failConfig{}, + }, + }, &request) + + result := pipeline.Evaluate() + assert.Equal(t, result.Code, rpc.PERMISSION_DENIED) + + fields := pipeline.loggingFields(1024) + + assert.Equal(t, "true", fields["logging.identity_anonymous"]) + assert.Equal(t, "POST", fields["logging.req_method"]) +} + +func TestLoggingFieldsGracefulOnAuthnFailure(t *testing.T) { + reqJSON := `{ + "attributes": { + "metadata_context": { + "filter_metadata": { + "io.kuadrant.logging.fields": { + "identity_anonymous": { "cel_expr": "auth.identity.anonymous" }, + "req_method": { "cel_expr": "request.method" } + } + } + }, + "request": { + "http": { + "host": "my-api", + "path": "/v1/chat/completions", + "method": "POST" + } + } + } + }` + + var request envoy_auth.CheckRequest + _ = gojson.Unmarshal([]byte(reqJSON), &request) + + pipeline := newTestAuthPipeline(evaluators.AuthConfig{ + IdentityConfigs: []auth.AuthConfigEvaluator{ + &failConfig{}, + }, + }, &request) + + result := pipeline.Evaluate() + assert.Equal(t, result.Code, rpc.UNAUTHENTICATED) + + fields := pipeline.loggingFields(1024) + + _, hasIdentity := fields["logging.identity_anonymous"] + assert.Check(t, !hasIdentity, "identity field should not resolve when authentication fails") + assert.Equal(t, "POST", fields["logging.req_method"]) +}