From 6e741f722d4acb10c461b9c430dddf7c28039c35 Mon Sep 17 00:00:00 2001 From: Guilherme Cassolato Date: Thu, 21 Oct 2021 18:17:13 +0200 Subject: [PATCH] Enhanced logging (#172) * Enhanced log messages and configuration * Auth request and response log messages repeated for info and debug This is useful so parsers can focus in either one log level or the other, without missing info when switching levels. Debug version of these log messages continue to include extra info, both about the request and response. * Log trace id * [docs] Logging * Loggers injected along the call stack * Rename log.Debug() -> log.IsDebug() * Request/response info log messages for the oidc service [fix] avoid panicking when the uri is insufficient to find a wristband config in the cache * log.Level removed No need to store log level. We can use `logr.Enabled()`. * Added .vscode to .(git|docker)ignore * Logger injected in the context instead of propagated directly into the stack * Some polishing + bug fix in the incoming authorization request debug log message (object was being stringified) --- .dockerignore | 1 + .gitignore | 1 + controllers/auth_config_controller.go | 23 +- controllers/auth_config_controller_test.go | 3 +- controllers/auth_config_status_updater.go | 6 + .../auth_config_status_updater_test.go | 2 + controllers/secret_controller.go | 7 +- controllers/secret_controller_test.go | 3 +- docs/contributing.md | 7 + docs/logging.md | 248 +++++++++++++++++ go.mod | 2 + main.go | 42 +-- pkg/cache/cache_test.go | 2 +- pkg/common/auth.go | 26 +- .../auth_credentials/auth_credentials.go | 12 +- pkg/common/log/log.go | 182 ++++++++++++ pkg/common/log/log_test.go | 104 +++++++ pkg/common/log/mocks/mock_logr.go | 260 ++++++++++++++++++ pkg/common/mocks/mock_common.go | 28 +- pkg/config/authorization.go | 15 +- pkg/config/authorization/kubernetes_authz.go | 3 + pkg/config/authorization/opa.go | 12 +- pkg/config/authorization/opa_test.go | 11 +- pkg/config/identity.go | 13 +- pkg/config/identity/api_key.go | 15 +- pkg/config/identity/api_key_test.go | 18 +- pkg/config/identity/kubernetes_auth.go | 3 + pkg/config/identity/oauth2.go | 6 +- pkg/config/identity/oidc.go | 20 +- pkg/config/metadata.go | 49 ++-- pkg/config/metadata/generic_http.go | 15 + pkg/config/metadata/uma.go | 12 +- pkg/config/metadata/user_info.go | 8 +- pkg/config/metadata/user_info_test.go | 4 +- pkg/config/response.go | 26 +- pkg/service/auth.go | 126 ++++++--- pkg/service/auth_pipeline.go | 87 +++--- pkg/service/auth_pipeline_test.go | 38 +-- pkg/service/auth_test.go | 16 +- pkg/service/oidc.go | 76 ++--- 40 files changed, 1233 insertions(+), 299 deletions(-) create mode 100644 docs/logging.md create mode 100644 pkg/common/log/log.go create mode 100644 pkg/common/log/log_test.go create mode 100644 pkg/common/log/mocks/mock_logr.go diff --git a/.dockerignore b/.dockerignore index 4c44e236..38403bab 100644 --- a/.dockerignore +++ b/.dockerignore @@ -9,3 +9,4 @@ examples tmp .idea +.vscode diff --git a/.gitignore b/.gitignore index 1f23553f..918cfc9c 100644 --- a/.gitignore +++ b/.gitignore @@ -18,6 +18,7 @@ vendor # editor and IDE paraphernalia .idea +.vscode *.swp *.swo *~ diff --git a/controllers/auth_config_controller.go b/controllers/auth_config_controller.go index 1a659036..5559c08d 100644 --- a/controllers/auth_config_controller.go +++ b/controllers/auth_config_controller.go @@ -25,6 +25,7 @@ import ( "github.com/kuadrant/authorino/pkg/cache" "github.com/kuadrant/authorino/pkg/common" "github.com/kuadrant/authorino/pkg/common/auth_credentials" + "github.com/kuadrant/authorino/pkg/common/log" "github.com/kuadrant/authorino/pkg/config" authorinoService "github.com/kuadrant/authorino/pkg/config" authorinoAuthorization "github.com/kuadrant/authorino/pkg/config/authorization" @@ -45,7 +46,7 @@ import ( // AuthConfigReconciler reconciles an AuthConfig object type AuthConfigReconciler struct { client.Client - Log logr.Logger + Logger logr.Logger Scheme *runtime.Scheme Cache cache.Cache } @@ -53,7 +54,7 @@ type AuthConfigReconciler struct { // +kubebuilder:rbac:groups=authorino.3scale.net,resources=authconfigs,verbs=get;list;watch;create;update;patch;delete func (r *AuthConfigReconciler) Reconcile(ctx context.Context, req ctrl.Request) (ctrl.Result, error) { - log := r.Log.WithValues("authConfig", req.NamespacedName) + logger := r.Logger.WithValues("authconfig", req.NamespacedName) authConfig := configv1beta1.AuthConfig{} err := r.Get(ctx, req.NamespacedName, &authConfig) @@ -61,7 +62,7 @@ func (r *AuthConfigReconciler) Reconcile(ctx context.Context, req ctrl.Request) // As we can't get the object, that means it was deleted. // Delete all the authconfigs related to this k8s object. - log.Info("object has been deleted, deleted related configs", "object", req) + logger.Info("object has been deleted, deleted related configs") //Cleanup all the hosts related to this CRD object. r.Cache.Delete(req.String()) @@ -73,7 +74,7 @@ func (r *AuthConfigReconciler) Reconcile(ctx context.Context, req ctrl.Request) } // The object exists so we need to either create it or update - authConfigByHost, err := r.translateAuthConfig(ctx, &authConfig) + authConfigByHost, err := r.translateAuthConfig(log.IntoContext(ctx, logger), &authConfig) if err != nil { return ctrl.Result{}, err } @@ -82,7 +83,7 @@ func (r *AuthConfigReconciler) Reconcile(ctx context.Context, req ctrl.Request) // Check for host collision with another namespace if cachedKey, found := r.Cache.FindId(host); found { if cachedKeyParts := strings.Split(cachedKey, string(types.Separator)); cachedKeyParts[0] != req.Namespace { - log.Info("host already taken in another namespace", "host", host) + logger.Info("host already taken in another namespace", "host", host) return ctrl.Result{}, nil } } @@ -92,12 +93,17 @@ func (r *AuthConfigReconciler) Reconcile(ctx context.Context, req ctrl.Request) } } + logger.Info("resource reconciled") + return ctrl.Result{}, nil } func (r *AuthConfigReconciler) translateAuthConfig(ctx context.Context, authConfig *configv1beta1.AuthConfig) (map[string]authorinoService.APIConfig, error) { + var ctxWithLogger context.Context + identityConfigs := make([]config.IdentityConfig, 0) interfacedIdentityConfigs := make([]common.AuthConfigEvaluator, 0) + ctxWithLogger = log.IntoContext(ctx, log.FromContext(ctx).WithName("identity")) for _, identity := range authConfig.Spec.Identity { extendedProperties := make([]common.JSONProperty, 0) @@ -141,11 +147,11 @@ func (r *AuthConfigReconciler) translateAuthConfig(ctx context.Context, authConf // oidc case configv1beta1.IdentityOidc: - translatedIdentity.OIDC = authorinoIdentity.NewOIDC(identity.Oidc.Endpoint, authCred) + translatedIdentity.OIDC = authorinoIdentity.NewOIDC(identity.Oidc.Endpoint, authCred, ctxWithLogger) // apiKey case configv1beta1.IdentityApiKey: - translatedIdentity.APIKey = authorinoIdentity.NewApiKeyIdentity(identity.Name, identity.APIKey.LabelSelectors, authCred, r.Client) + translatedIdentity.APIKey = authorinoIdentity.NewApiKeyIdentity(identity.Name, identity.APIKey.LabelSelectors, authCred, r.Client, ctxWithLogger) // kubernetes auth case configv1beta1.IdentityKubernetesAuth: @@ -247,6 +253,7 @@ func (r *AuthConfigReconciler) translateAuthConfig(ctx context.Context, authConf } interfacedAuthorizationConfigs := make([]common.AuthConfigEvaluator, 0) + ctxWithLogger = log.IntoContext(ctx, log.FromContext(ctx).WithName("authorization")) for index, authorization := range authConfig.Spec.Authorization { translatedAuthorization := &config.AuthorizationConfig{ @@ -279,7 +286,7 @@ func (r *AuthConfigReconciler) translateAuthConfig(ctx context.Context, authConf } var err error - translatedAuthorization.OPA, err = authorinoAuthorization.NewOPAAuthorization(policyName, opa.InlineRego, externalSource, index) + translatedAuthorization.OPA, err = authorinoAuthorization.NewOPAAuthorization(policyName, opa.InlineRego, externalSource, index, ctxWithLogger) if err != nil { return nil, err } diff --git a/controllers/auth_config_controller_test.go b/controllers/auth_config_controller_test.go index e6f53244..bcf8e6f3 100644 --- a/controllers/auth_config_controller_test.go +++ b/controllers/auth_config_controller_test.go @@ -8,6 +8,7 @@ import ( "github.com/kuadrant/authorino/api/v1beta1" "github.com/kuadrant/authorino/pkg/cache" mock_cache "github.com/kuadrant/authorino/pkg/cache/mocks" + "github.com/kuadrant/authorino/pkg/common/log" mocks "github.com/kuadrant/authorino/pkg/common/mocks" "github.com/golang/mock/gomock" @@ -130,7 +131,7 @@ func setupEnvironment(t *testing.T, c cache.Cache) AuthConfigReconciler { return AuthConfigReconciler{ Client: client, - Log: ctrl.Log.WithName("reconcilerTest"), + Logger: log.WithName("test").WithName("authconfigreconciler"), Scheme: nil, Cache: c, } diff --git a/controllers/auth_config_status_updater.go b/controllers/auth_config_status_updater.go index 2a23030f..514834d9 100644 --- a/controllers/auth_config_status_updater.go +++ b/controllers/auth_config_status_updater.go @@ -5,6 +5,7 @@ import ( configv1beta1 "github.com/kuadrant/authorino/api/v1beta1" + "github.com/go-logr/logr" "k8s.io/apimachinery/pkg/api/errors" ctrl "sigs.k8s.io/controller-runtime" "sigs.k8s.io/controller-runtime/pkg/client" @@ -13,12 +14,15 @@ import ( // AuthConfigStatusUpdater updates the status of a newly reconciled auth config type AuthConfigStatusUpdater struct { client.Client + Logger logr.Logger } // +kubebuilder:rbac:groups=authorino.3scale.net,resources=authconfigs/status,verbs=get;update;patch // +kubebuilder:rbac:groups=coordination.k8s.io,resources=leases,verbs=get;list;create;update func (u *AuthConfigStatusUpdater) Reconcile(ctx context.Context, req ctrl.Request) (ctrl.Result, error) { + logger := u.Logger.WithValues("authconfig/status", req.NamespacedName) + authConfig := configv1beta1.AuthConfig{} err := u.Get(ctx, req.NamespacedName, &authConfig) @@ -28,6 +32,8 @@ func (u *AuthConfigStatusUpdater) Reconcile(ctx context.Context, req ctrl.Reques return ctrl.Result{}, err } + logger.Info("resource status updated") + return ctrl.Result{}, u.updateAuthConfigStatus(ctx, &authConfig, true) } diff --git a/controllers/auth_config_status_updater_test.go b/controllers/auth_config_status_updater_test.go index 4fcdfe79..24b5f6b5 100644 --- a/controllers/auth_config_status_updater_test.go +++ b/controllers/auth_config_status_updater_test.go @@ -5,6 +5,7 @@ import ( "testing" "github.com/kuadrant/authorino/api/v1beta1" + "github.com/kuadrant/authorino/pkg/common/log" "gotest.tools/assert" v1 "k8s.io/api/core/v1" @@ -47,6 +48,7 @@ func TestAuthConfigStatusUpdaterReconcile(t *testing.T) { result, err := (&AuthConfigStatusUpdater{ Client: client, + Logger: log.WithName("test").WithName("authconfigstatusupdater"), }).Reconcile(context.Background(), controllerruntime.Request{ NamespacedName: resourceName, }) diff --git a/controllers/secret_controller.go b/controllers/secret_controller.go index 34c3dcbe..c802dafc 100644 --- a/controllers/secret_controller.go +++ b/controllers/secret_controller.go @@ -27,7 +27,7 @@ var newController = controller_builder.NewControllerManagedBy // SecretReconciler reconciles k8s Secret objects type SecretReconciler struct { client.Client - Log logr.Logger + Logger logr.Logger Scheme *runtime.Scheme SecretLabel string AuthConfigReconciler reconcile.Reconciler @@ -36,7 +36,7 @@ type SecretReconciler struct { // +kubebuilder:rbac:groups=core,resources=secrets,verbs=get;list;watch; func (r *SecretReconciler) Reconcile(ctx context.Context, req ctrl.Request) (ctrl.Result, error) { - log := r.Log.WithValues("secret", req.NamespacedName) + logger := r.Logger.WithValues("secret", req.NamespacedName) var reconcile func(configv1beta1.AuthConfig) @@ -81,9 +81,10 @@ func (r *SecretReconciler) Reconcile(ctx context.Context, req ctrl.Request) (ctr } if err := r.reconcileAuthConfigsUsingAPIKey(ctx, req.Namespace, reconcile); err != nil { - log.Info("could not reconcile authconfigs using api key authentication", "req", req) + logger.Info("could not reconcile authconfigs using api key authentication") return ctrl.Result{}, err } else { + logger.Info("resource reconciled") return ctrl.Result{}, nil } } diff --git a/controllers/secret_controller_test.go b/controllers/secret_controller_test.go index f4830a9c..bd4ca286 100644 --- a/controllers/secret_controller_test.go +++ b/controllers/secret_controller_test.go @@ -9,6 +9,7 @@ import ( "github.com/kuadrant/authorino/api/v1beta1" controller_builder "github.com/kuadrant/authorino/controllers/builder" mock_controller_builder "github.com/kuadrant/authorino/controllers/builder/mocks" + "github.com/kuadrant/authorino/pkg/common/log" "github.com/golang/mock/gomock" v1 "k8s.io/api/core/v1" @@ -111,7 +112,7 @@ func newSecretReconcilerTest(secretLabels map[string]string) secretReconcilerTes } secretReconciler := &SecretReconciler{ Client: client, - Log: ctrl.Log.WithName("reconcilerTest"), + Logger: log.WithName("test").WithName("secretreconciler"), Scheme: nil, SecretLabel: "authorino.3scale.net/managed-by", AuthConfigReconciler: authConfigReconciler, diff --git a/docs/contributing.md b/docs/contributing.md index f5452c3a..54373625 100644 --- a/docs/contributing.md +++ b/docs/contributing.md @@ -32,3 +32,10 @@ make vendor - [Examples](../examples/) - [Deployment instructions](deploy.md) - [Code of Conduct](code_of_conduct.md) + +## Logging messages + +A few guidelines for adding logging messages in your code: +1. Make sure you understand Authorino's [Logging](logging.md) architecture and policy regarding log levels, log modes, tracing IDs, etc. +2. Respect controller-runtime's [Logging Guidelines](https://github.com/kubernetes-sigs/controller-runtime/blob/master/TMP-LOGGING.md). +3. Do not add sensitive data to your `info` log messages; instead, redact all sensitive data in your log messages or use `debug` log level by mutating the logger with `V(1)` before outputting the message. diff --git a/docs/logging.md b/docs/logging.md new file mode 100644 index 00000000..717f18e3 --- /dev/null +++ b/docs/logging.md @@ -0,0 +1,248 @@ +# Logging + +## Log levels and log modes + +Authorino outputs 3 levels of log messages: (from lowest to highest level) +1. `debug` +2. `info` (default) +3. `error` + +`info` logging is restricted to high-level information of the gRPC and HTTP authorization services, limiting messages to incomming request and respective outgoing response logs, with reduced details about the corresponding objects (request payload and authorization result), and without any further detailed logs of the steps in between, except for errors. + +Only `debug` logging will include processing details of each [Auth Pipeline](architecture.md#the-auth-pipeline), such as intermediary requests to validate identities with external auth servers, requests to external sources of auth metadata or authorization policies. + +To configure the desired log level, set the environment variable `LOG_LEVEL` to one of the supported values listed above. Default log level is `info`. + +Apart from log level, Authorino can output messages to the logs in 2 different formats: +- `production` (default): each line is a parseable JSON object with properties `{"level":string, "ts":int, "msg":string, "logger":string, extra values...}` +- `development`: more human-readable outputs, extra stack traces and logging info, plus extra values output as JSON, in the format: `\t\t\t\t{extra-values-as-json}` + +To configure the desired log mode, set the environment variable `LOG_MODE` to one of the supported values listed above. Default log level is `production`. + +## Sensitive data output to the logs + +Authorino will never output HTTP headers and query string parameters to `info` log messages, as such values usually include sensitive data (e.g. access tokens, API keys and Authorino [Festival Wristbands](architecture.md#festival-wristband-authentication)). However, `debug` log messages may include such sensitive information and those are not redacted. + +Therefore, **DO NOT USE `debug` LOG LEVEL IN PRODUCTION**! Instead use either `info` or `error`. + +## Tracing ID + +Most log messages associated with an auth request include a `request id` extra value. The value represents the ID of the external authorization request received and processed by Authorino. This value is particularly useful to link incomming request and outgoing response log messages, as well as the more fine-grained log details available only in `debug` level. + +## Typical log messages + +Some typical log messages output by the Authorino service are listed in the table below: + +| logger | level | message | extra values | +| -------|-------|---------|--------| +| `authorino` | `info` | "setting instance base logger" | `min level=info\|debug`, `mode=production\|development` | +| `authorino` | `info` | "attempting to acquire leader lease authorino/cb88a58a.authorino.3scale.net...\n" | | +| `authorino` | `info` | "successfully acquired lease authorino/cb88a58a.authorino.3scale.net\n" | | +| `authorino` | `info` | "starting grpc service" | `port`, `tls` | +| `authorino` | `error` | "failed to obtain port for grpc auth service" | | +| `authorino` | `error` | "failed to load tls cert" | | +| `authorino` | `error` | "failed to start grpc service" | | +| `authorino` | `info` | "starting oidc service" | `port`, `tls` | +| `authorino` | `error` | "failed to obtain port for http oidc service" | | +| `authorino` | `error` | "failed to start oidc service" | | +| `authorino` | `info` | "starting manager" | | +| `authorino` | `error` | "unable to start manager" | | +| `authorino` | `error` | "unable to create controller" | `controller=authconfig\|secret\|authconfigstatusupdate` | +| `authorino` | `error` | "problem running manager" | | +| `authorino` | `info` | "starting status update manager" | | +| `authorino` | `error` | "unable to start status update manager" | | +| `authorino` | `error` | "problem running status update manager" | | +| `authorino.controller-runtime.metrics` | `info` | "metrics server is starting to listen" | `addr` | +| `authorino.controller-runtime.manager` | `info` | "starting metrics server" | `path` +| `authorino.controller-runtime.manager.events` | `debug` | "Normal" | `object={kind=ConfigMap, apiVersion=v1}`, `reauthorino.ason=LeaderElection`, `message="authorino-controller-manager-* became leader"` +| `authorino.controller-runtime.manager.events` | `debug` | "Normal" | `object={kind=Lease, apiVersion=coordination.k8s.io/v1}`, `reauthorino.ason=LeaderElection`, `message="authorino-controller-manager-* became leader"` +| `authorino.controller-runtime.manager.controller.authconfig` | `info` | "resource reconciled" | | +| `authorino.controller-runtime.manager.controller.authconfig` | `info` | "object has been deleted, deleted related configs" | | +| `authorino.controller-runtime.manager.controller.authconfig` | `info` | "host already taken in another namespace" | | +| `authorino.controller-runtime.manager.controller.authconfig.statusupdater` | `info` | "resource status updated" | | +| `authorino.controller-runtime.manager.controller.secret` | `info` | "resource reconciled" | | +| `authorino.controller-runtime.manager.controller.secret` | `info` | "could not reconcile authconfigs using api key autauthorino.hentication" | | +| `authorino.service.oidc` | `info` | "request received" | `request id`, `url`, `realm`, `config`, `path` | +| `authorino.service.oidc` | `info` | "response sent" | `request id` | +| `authorino.service.oidc` | `error` | "failed to serve oidc request" | | +| `authorino.service.auth` | `info` | "incoming authorization request" | `request id`, `object` | +| `authorino.service.auth` | `debug` | "incoming authorization request" | `request id`, `object` | +| `authorino.service.auth` | `info` | "outgoing authorization response" | `request id`, `authorized`, `response`, `object` | +| `authorino.service.auth` | `debug` | "outgoing authorization response" | `request id`, `authorized`, `response`, `object` | +| `authorino.service.auth` | `error` | "failed to create dynamic metadata" | `request id`, `object` | +| `authorino.service.auth.authpipeline` | `debug` | "skipping config" | `request id`, `config`, `reason` | +| `authorino.service.auth.authpipeline.identity` | `debug` | "identity validated" | `request id`, `config`, `object` | +| `authorino.service.auth.authpipeline.identity` | `debug` | "cannot validate identity" | `request id`, `config`, `reason` | +| `authorino.service.auth.authpipeline.identity` | `error` | "failed to extend identity object" | `request id`, `config`, `object` | +| `authorino.service.auth.authpipeline.identity.oidc` | `error` | "failed to discovery openid connect configuration" | `endpoint` | +| `authorino.service.auth.authpipeline.identity.oauth2` | `debug` | "sending token introspection request" | `request id`, `url`, `data` | +| `authorino.service.auth.authpipeline.identity.kubernetesauth` | `debug` | "calling kubernetes token review api" | `request id`, `tokenreview` | +| `authorino.service.auth.authpipeline.identity.apikey` | `error` | "Something went wrong fetching the authorized credentials" | | +| `authorino.service.auth.authpipeline.metadata` | `debug` | "fetched auth metadata" | `request id`, `config`, `object` | +| `authorino.service.auth.authpipeline.metadata` | `debug` | "cannot fetch metadata" | `request id`, `config`, `reason` | +| `authorino.service.auth.authpipeline.metadata.http` | `debug` | "sending request" | `request id`, `method`, `url`, `headers` | +| `authorino.service.auth.authpipeline.metadata.userinfo` | `debug` | "fetching user info" | `request id`, `endpoint` | +| `authorino.service.auth.authpipeline.metadata.uma` | `debug` | "requesting pat" | `request id`, `url`, `data`, `headers` | +| `authorino.service.auth.authpipeline.metadata.uma` | `debug` | "querying resources by uri" | `request id`, `url` | +| `authorino.service.auth.authpipeline.metadata.uma` | `debug` | "getting resource data" | `request id`, `url` | +| `authorino.service.auth.authpipeline.authorization` | `debug` | "evaluating for input" | `request id`, `input` | +| `authorino.service.auth.authpipeline.authorization` | `debug` | "access granted" | `request id`, `config`, `object` | +| `authorino.service.auth.authpipeline.authorization` | `debug` | "access denied" | `request id`, `config`, `reason` | +| `authorino.service.auth.authpipeline.authorization.opa` | `error` | "Invalid response from OPA policy evaluation" | `secret` | +| `authorino.service.auth.authpipeline.authorization.opa` | `error` | "Failed to precompile OPA policy" | `secret` | +| `authorino.service.auth.authpipeline.authorization.kubernetesauthz` | `debug` | "calling kubernetes subject access review api" | `request id`, `subjectaccessreview` | +| `authorino.service.auth.authpipeline.response` | `debug` | "dynamic response built" | `request id`, `config`, `object` | +| `authorino.service.auth.authpipeline.response` | `debug` | "cannot build dynamic response" | `request id`, `config`, `reason` | +| `authorino.authcredential` | `error` | "the credential was not found in the request header" | | +| `authorino.authcredential` | `error` | "the Authorization header is not set" | | +| `authorino.authcredential` | `error` | "the Cookie header is not set" | | + +### Examples + +The examples below are all with `LOG_LEVEL=debug` and `LOG_MODE=production`. + +#### Booting up the service: + +```jsonc +{"level":"info","ts":1634674939.7563884,"logger":"authorino","msg":"setting instance base logger","min level":"debug","mode":"production"} +{"level":"info","ts":1634674941.0670755,"logger":"authorino.controller-runtime.metrics","msg":"metrics server is starting to listen","addr":"127.0.0.1:8080"} +{"level":"info","ts":1634674941.0946925,"logger":"authorino","msg":"starting grpc service","port":"50051","tls":true} +{"level":"info","ts":1634674941.103486,"logger":"authorino","msg":"starting oidc service","port":"8083","tls":true} +{"level":"info","ts":1634674941.1678321,"logger":"authorino","msg":"starting manager"} +{"level":"info","ts":1634674941.1765432,"logger":"authorino.controller-runtime.manager.controller.authconfig","msg":"Starting EventSource","reconciler group":"authorino.3scale.net","reconciler kind":"AuthConfig","source":"kind source: /, Kind="} +{"level":"info","ts":1634674941.182127,"logger":"authorino.controller-runtime.manager.controller.authconfig","msg":"Starting Controller","reconciler group":"authorino.3scale.net","reconciler kind":"AuthConfig"} +{"level":"info","ts":1634674941.1928735,"logger":"authorino.controller-runtime.manager.controller.secret","msg":"Starting EventSource","reconciler group":"","reconciler kind":"Secret","source":"kind source: /, Kind="} +{"level":"info","ts":1634674941.1951146,"logger":"authorino.controller-runtime.manager.controller.secret","msg":"Starting Controller","reconciler group":"","reconciler kind":"Secret"} +{"level":"info","ts":1634674941.203209,"logger":"authorino.controller-runtime.manager","msg":"starting metrics server","path":"/metrics"} +{"level":"info","ts":1634674942.256725,"logger":"authorino.controller-runtime.manager.controller.secret","msg":"Starting workers","reconciler group":"","reconciler kind":"Secret","worker count":1} +{"level":"info","ts":1634674942.2595103,"logger":"authorino.controller-runtime.manager.controller.authconfig","msg":"Starting workers","reconciler group":"authorino.3scale.net","reconciler kind":"AuthConfig","worker count":1} +{"level":"info","ts":1634674942.5573237,"logger":"authorino","msg":"starting status update manager"} +{"level":"info","ts":1634674942.5718815,"logger":"authorino","msg":"attempting to acquire leader lease authorino/cb88a58a.authorino.3scale.net...\n"} +{"level":"info","ts":1634674959.4286165,"logger":"authorino","msg":"successfully acquired lease authorino/cb88a58a.authorino.3scale.net\n"} +{"level":"info","ts":1634674959.4316218,"logger":"authorino.controller-runtime.manager.controller.authconfig","msg":"Starting EventSource","reconciler group":"authorino.3scale.net","reconciler kind":"AuthConfig","source":"kind source: /, Kind="} +{"level":"info","ts":1634674959.4348314,"logger":"authorino.controller-runtime.manager.controller.authconfig","msg":"Starting Controller","reconciler group":"authorino.3scale.net","reconciler kind":"AuthConfig"} +{"level":"debug","ts":1634674959.4354987,"logger":"authorino.controller-runtime.manager.events","msg":"Normal","object":{"kind":"ConfigMap","namespace":"authorino","name":"cb88a58a.authorino.3scale.net","uid":"fcefe0d5-87f6-4a01-8e80-7cf290bc269b","apiVersion":"v1","resourceVersion":"55791"},"reason":"LeaderElection","message":"authorino-controller-manager-5d86dbb56f-th8mf_c416d2c6-fe44-421b-a025-344a60b70614 became leader"} +{"level":"debug","ts":1634674959.5168512,"logger":"authorino.controller-runtime.manager.events","msg":"Normal","object":{"kind":"Lease","namespace":"authorino","name":"cb88a58a.authorino.3scale.net","uid":"2753012c-4a06-4cb3-93c9-857d092bf289","apiVersion":"coordination.k8s.io/v1","resourceVersion":"55792"},"reason":"LeaderElection","message":"authorino-controller-manager-5d86dbb56f-th8mf_c416d2c6-fe44-421b-a025-344a60b70614 became leader"} +{"level":"info","ts":1634674959.5356445,"logger":"authorino.controller-runtime.manager.controller.authconfig","msg":"Starting workers","reconciler group":"authorino.3scale.net","reconciler kind":"AuthConfig","worker count":1} +``` + +#### Reconciling an `AuthConfig` and 2 related API key `Secret`s: + +```jsonc +{"level":"info","ts":1634675069.1662104,"logger":"authorino.controller-runtime.manager.controller.authconfig.statusupdater","msg":"resource status updated","authconfig/status":"authorino/talker-api-protection"} +{"level":"info","ts":1634675069.2253225,"logger":"authorino.controller-runtime.manager.controller.authconfig.statusupdater","msg":"resource status updated","authconfig/status":"authorino/talker-api-protection"} +{"level":"info","ts":1634675069.3370266,"logger":"authorino.controller-runtime.manager.controller.secret","msg":"resource reconciled","secret":"authorino/api-key-1"} +{"level":"info","ts":1634675069.3740098,"logger":"authorino.controller-runtime.manager.controller.secret","msg":"resource reconciled","secret":"authorino/api-key-2"} +{"level":"info","ts":1634675069.9157252,"logger":"authorino.controller-runtime.manager.controller.authconfig","msg":"resource reconciled","authconfig":"authorino/talker-api-protection"} +{"level":"info","ts":1634675069.9188104,"logger":"authorino.controller-runtime.manager.controller.authconfig","msg":"resource reconciled","authconfig":"authorino/talker-api-protection"} +{"level":"info","ts":1634675069.9242647,"logger":"authorino.controller-runtime.manager.controller.authconfig","msg":"resource reconciled","authconfig":"authorino/talker-api-protection"} +{"level":"info","ts":1634675070.1129518,"logger":"authorino.controller-runtime.manager.controller.authconfig","msg":"resource reconciled","authconfig":"authorino/talker-api-protection"} +``` + +#### Enforcing `AuthConfig` while authenticating with Kubernetes authentication token: + +
+ AuhConfig composed of: + + - identity: k8s-auth, oidc, oauth2, apikey + - metadata: http, oidc userinfo + - authorization: opa, k8s-authz + - response: wristband +
+ +```jsonc +{"level":"info","ts":1634830460.1486168,"logger":"authorino.service.auth","msg":"incoming authorization request","request id":"8157480586935853928","object":{"source":{"address":{"Address":{"SocketAddress":{"address":"127.0.0.1","PortSpecifier":{"PortValue":53144}}}}},"destination":{"address":{"Address":{"SocketAddress":{"address":"127.0.0.1","PortSpecifier":{"PortValue":8000}}}}},"request":{"http":{"id":"8157480586935853928","method":"GET","path":"/hello","host":"talker-api","scheme":"http"}}}} +{"level":"debug","ts":1634830460.1491194,"logger":"authorino.service.auth","msg":"incoming authorization request","request id":"8157480586935853928","object":{"source":{"address":{"Address":{"SocketAddress":{"address":"127.0.0.1","PortSpecifier":{"PortValue":53144}}}}},"destination":{"address":{"Address":{"SocketAddress":{"address":"127.0.0.1","PortSpecifier":{"PortValue":8000}}}}},"request":{"time":{"seconds":1634830460,"nanos":147259000},"http":{"id":"8157480586935853928","method":"GET","headers":{":authority":"talker-api",":method":"GET",":path":"/hello",":scheme":"http","accept":"*/*","authorization":"Bearer eyJhbGciOiJSUzI1NiIsImtpZCI6IkRsVWJZMENyVy1sZ0tFMVRMd19pcTFUWGtTYUl6T0hyWks0VHhKYnpEZUUifQ.eyJhdWQiOlsidGFsa2VyLWFwaSJdLCJleHAiOjE2MzQ4MzEwNTEsImlhdCI6MTYzNDgzMDQ1MSwiaXNzIjoiaHR0cHM6Ly9rdWJlcm5ldGVzLmRlZmF1bHQuc3ZjLmNsdXN0ZXIubG9jYWwiLCJrdWJlcm5ldGVzLmlvIjp7Im5hbWVzcGFjZSI6ImF1dGhvcmlubyIsInNlcnZpY2VhY2NvdW50Ijp7Im5hbWUiOiJhcGktY29uc3VtZXItMSIsInVpZCI6ImI0MGY1MzFjLWVjYWItNGYzMS1hNDk2LTJlYmM3MmFkZDEyMSJ9fSwibmJmIjoxNjM0ODMwNDUxLCJzdWIiOiJzeXN0ZW06c2VydmljZWFjY291bnQ6YXV0aG9yaW5vOmFwaS1jb25zdW1lci0xIn0.PaP0vqdl5DPfErr84KfVhPdlsGAPgsw0NkDaA9rne1zXjzcO7KPPbXhFwZC-oIjSGG1HfRMSoQeCXbQz24PSATmX8l1T52a9IFeXgP7sQmXZIDbiPfTm3X09kIIlfPKHhK_f-jQwRIpMRqNgLntlZ-xXX3P1fOBBUYR8obTPAQ6NDDaLHxw2SAmHFTQWjM_DInPDemXX0mEm7nCPKifsNxHaQH4wx4CD3LCLGbCI9FHNf2Crid8mmGJXf4wzcH1VuKkpUlsmnlUgTG2bfT2lbhSF2lBmrrhTJyYk6_aA09DwL4Bf4kvG-JtCq0Bkd_XynViIsOtOnAhgmdSPkfr-oA","user-agent":"curl/7.65.3","x-envoy-internal":"true","x-forwarded-for":"10.244.0.11","x-forwarded-proto":"http","x-request-id":"4c5d5c97-e15b-46a3-877a-d8188e09e08f"},"path":"/hello","host":"talker-api","scheme":"http","protocol":"HTTP/1.1"}},"context_extensions":{"virtual_host":"local_service"},"metadata_context":{}}} +{"level":"debug","ts":1634830460.150506,"logger":"authorino.service.auth.authpipeline.identity.kubernetesauth","msg":"calling kubernetes token review api","request id":"8157480586935853928","tokenreview":{"metadata":{"creationTimestamp":null},"spec":{"token":"eyJhbGciOiJSUzI1NiIsImtpZCI6IkRsVWJZMENyVy1sZ0tFMVRMd19pcTFUWGtTYUl6T0hyWks0VHhKYnpEZUUifQ.eyJhdWQiOlsidGFsa2VyLWFwaSJdLCJleHAiOjE2MzQ4MzEwNTEsImlhdCI6MTYzNDgzMDQ1MSwiaXNzIjoiaHR0cHM6Ly9rdWJlcm5ldGVzLmRlZmF1bHQuc3ZjLmNsdXN0ZXIubG9jYWwiLCJrdWJlcm5ldGVzLmlvIjp7Im5hbWVzcGFjZSI6ImF1dGhvcmlubyIsInNlcnZpY2VhY2NvdW50Ijp7Im5hbWUiOiJhcGktY29uc3VtZXItMSIsInVpZCI6ImI0MGY1MzFjLWVjYWItNGYzMS1hNDk2LTJlYmM3MmFkZDEyMSJ9fSwibmJmIjoxNjM0ODMwNDUxLCJzdWIiOiJzeXN0ZW06c2VydmljZWFjY291bnQ6YXV0aG9yaW5vOmFwaS1jb25zdW1lci0xIn0.PaP0vqdl5DPfErr84KfVhPdlsGAPgsw0NkDaA9rne1zXjzcO7KPPbXhFwZC-oIjSGG1HfRMSoQeCXbQz24PSATmX8l1T52a9IFeXgP7sQmXZIDbiPfTm3X09kIIlfPKHhK_f-jQwRIpMRqNgLntlZ-xXX3P1fOBBUYR8obTPAQ6NDDaLHxw2SAmHFTQWjM_DInPDemXX0mEm7nCPKifsNxHaQH4wx4CD3LCLGbCI9FHNf2Crid8mmGJXf4wzcH1VuKkpUlsmnlUgTG2bfT2lbhSF2lBmrrhTJyYk6_aA09DwL4Bf4kvG-JtCq0Bkd_XynViIsOtOnAhgmdSPkfr-oA","audiences":["talker-api"]},"status":{"user":{}}}} +{"level":"debug","ts":1634830460.1509938,"logger":"authorino.service.auth.authpipeline.identity","msg":"cannot validate identity","request id":"8157480586935853928","config":{"Name":"api-keys","ExtendedProperties":[{"Name":"sub","Value":{"Static":null,"Pattern":"auth.identity.metadata.annotations.userid"}}],"OAuth2":null,"OIDC":null,"MTLS":null,"HMAC":null,"APIKey":{"AuthCredentials":{"KeySelector":"APIKEY","In":"authorization_header"},"Name":"api-keys","LabelSelectors":{"audience":"talker-api","authorino.3scale.net/managed-by":"authorino"}},"KubernetesAuth":null},"reason":"credential not found"} +{"level":"debug","ts":1634830460.1517606,"logger":"authorino.service.auth.authpipeline.identity.oauth2","msg":"sending token introspection request","request id":"8157480586935853928","url":"http://talker-api:523b92b6-625d-4e1e-a313-77e7a8ae4e88@keycloak:8080/auth/realms/kuadrant/protocol/openid-connect/token/introspect","data":"token=eyJhbGciOiJSUzI1NiIsImtpZCI6IkRsVWJZMENyVy1sZ0tFMVRMd19pcTFUWGtTYUl6T0hyWks0VHhKYnpEZUUifQ.eyJhdWQiOlsidGFsa2VyLWFwaSJdLCJleHAiOjE2MzQ4MzEwNTEsImlhdCI6MTYzNDgzMDQ1MSwiaXNzIjoiaHR0cHM6Ly9rdWJlcm5ldGVzLmRlZmF1bHQuc3ZjLmNsdXN0ZXIubG9jYWwiLCJrdWJlcm5ldGVzLmlvIjp7Im5hbWVzcGFjZSI6ImF1dGhvcmlubyIsInNlcnZpY2VhY2NvdW50Ijp7Im5hbWUiOiJhcGktY29uc3VtZXItMSIsInVpZCI6ImI0MGY1MzFjLWVjYWItNGYzMS1hNDk2LTJlYmM3MmFkZDEyMSJ9fSwibmJmIjoxNjM0ODMwNDUxLCJzdWIiOiJzeXN0ZW06c2VydmljZWFjY291bnQ6YXV0aG9yaW5vOmFwaS1jb25zdW1lci0xIn0.PaP0vqdl5DPfErr84KfVhPdlsGAPgsw0NkDaA9rne1zXjzcO7KPPbXhFwZC-oIjSGG1HfRMSoQeCXbQz24PSATmX8l1T52a9IFeXgP7sQmXZIDbiPfTm3X09kIIlfPKHhK_f-jQwRIpMRqNgLntlZ-xXX3P1fOBBUYR8obTPAQ6NDDaLHxw2SAmHFTQWjM_DInPDemXX0mEm7nCPKifsNxHaQH4wx4CD3LCLGbCI9FHNf2Crid8mmGJXf4wzcH1VuKkpUlsmnlUgTG2bfT2lbhSF2lBmrrhTJyYk6_aA09DwL4Bf4kvG-JtCq0Bkd_XynViIsOtOnAhgmdSPkfr-oA&token_type_hint=requesting_party_token"} +{"level":"debug","ts":1634830460.1620777,"logger":"authorino.service.auth.authpipeline.identity","msg":"identity validated","request id":"8157480586935853928","config":{"Name":"k8s-service-accounts","ExtendedProperties":[],"OAuth2":null,"OIDC":null,"MTLS":null,"HMAC":null,"APIKey":null,"KubernetesAuth":{"AuthCredentials":{"KeySelector":"Bearer","In":"authorization_header"}}},"object":{"aud":["talker-api"],"exp":1634831051,"iat":1634830451,"iss":"https://kubernetes.default.svc.cluster.local","kubernetes.io":{"namespace":"authorino","serviceaccount":{"name":"api-consumer-1","uid":"b40f531c-ecab-4f31-a496-2ebc72add121"}},"nbf":1634830451,"sub":"system:serviceaccount:authorino:api-consumer-1"}} +{"level":"debug","ts":1634830460.1622565,"logger":"authorino.service.auth.authpipeline.metadata.uma","msg":"requesting pat","request id":"8157480586935853928","url":"http://talker-api:523b92b6-625d-4e1e-a313-77e7a8ae4e88@keycloak:8080/auth/realms/kuadrant/protocol/openid-connect/token","data":"grant_type=client_credentials","headers":{"Content-Type":["application/x-www-form-urlencoded"]}} +{"level":"debug","ts":1634830460.1670353,"logger":"authorino.service.auth.authpipeline.metadata.http","msg":"sending request","request id":"8157480586935853928","method":"GET","url":"http://talker-api.authorino.svc.cluster.local:3000/metadata?encoding=text/plain&original_path=/hello","headers":{"Content-Type":["text/plain"]}} +{"level":"debug","ts":1634830460.169326,"logger":"authorino.service.auth.authpipeline.metadata","msg":"cannot fetch metadata","request id":"8157480586935853928","config":{"Name":"oidc-userinfo","UserInfo":{"OIDC":{"AuthCredentials":{"KeySelector":"Bearer","In":"authorization_header"},"Endpoint":"http://keycloak:8080/auth/realms/kuadrant"}},"UMA":null,"GenericHTTP":null},"reason":"Missing identity for OIDC issuer http://keycloak:8080/auth/realms/kuadrant. Skipping related UserInfo metadata."} +{"level":"debug","ts":1634830460.1753876,"logger":"authorino.service.auth.authpipeline.metadata","msg":"fetched auth metadata","request id":"8157480586935853928","config":{"Name":"http-metadata","UserInfo":null,"UMA":null,"GenericHTTP":{"Endpoint":"http://talker-api.authorino.svc.cluster.local:3000/metadata?encoding=text/plain&original_path={context.request.http.path}","Method":"GET","Parameters":[],"ContentType":"application/x-www-form-urlencoded","SharedSecret":"","AuthCredentials":{"KeySelector":"Bearer","In":"authorization_header"}}},"object":{"body":"","headers":{"Accept-Encoding":"gzip","Content-Type":"text/plain","Host":"talker-api.authorino.svc.cluster.local:3000","User-Agent":"Go-http-client/1.1","Version":"HTTP/1.1"},"method":"GET","path":"/metadata","query_string":"encoding=text/plain&original_path=/hello","uuid":"1aa6ac66-3179-4351-b1a7-7f6a761d5b61"}} +{"level":"debug","ts":1634830460.2331996,"logger":"authorino.service.auth.authpipeline.metadata.uma","msg":"querying resources by uri","request id":"8157480586935853928","url":"http://keycloak:8080/auth/realms/kuadrant/authz/protection/resource_set?uri=/hello"} +{"level":"debug","ts":1634830460.2495668,"logger":"authorino.service.auth.authpipeline.metadata.uma","msg":"getting resource data","request id":"8157480586935853928","url":"http://keycloak:8080/auth/realms/kuadrant/authz/protection/resource_set/e20d194c-274c-4845-8c02-0ca413c9bf18"} +{"level":"debug","ts":1634830460.2927864,"logger":"authorino.service.auth.authpipeline.metadata","msg":"fetched auth metadata","request id":"8157480586935853928","config":{"Name":"uma-resource-registry","UserInfo":null,"UMA":{"Endpoint":"http://keycloak:8080/auth/realms/kuadrant","ClientID":"talker-api","ClientSecret":"523b92b6-625d-4e1e-a313-77e7a8ae4e88"},"GenericHTTP":null},"object":[{"_id":"e20d194c-274c-4845-8c02-0ca413c9bf18","attributes":{},"displayName":"hello","name":"hello","owner":{"id":"57a645a5-fb67-438b-8be5-dfb971666dbc"},"ownerManagedAccess":false,"resource_scopes":[],"uris":["/hi","/hello"]}]} +{"level":"debug","ts":1634830460.2930083,"logger":"authorino.service.auth.authpipeline.authorization","msg":"evaluating for input","request id":"8157480586935853928","input":{"context":{"source":{"address":{"Address":{"SocketAddress":{"address":"127.0.0.1","PortSpecifier":{"PortValue":53144}}}}},"destination":{"address":{"Address":{"SocketAddress":{"address":"127.0.0.1","PortSpecifier":{"PortValue":8000}}}}},"request":{"time":{"seconds":1634830460,"nanos":147259000},"http":{"id":"8157480586935853928","method":"GET","headers":{":authority":"talker-api",":method":"GET",":path":"/hello",":scheme":"http","accept":"*/*","authorization":"Bearer eyJhbGciOiJSUzI1NiIsImtpZCI6IkRsVWJZMENyVy1sZ0tFMVRMd19pcTFUWGtTYUl6T0hyWks0VHhKYnpEZUUifQ.eyJhdWQiOlsidGFsa2VyLWFwaSJdLCJleHAiOjE2MzQ4MzEwNTEsImlhdCI6MTYzNDgzMDQ1MSwiaXNzIjoiaHR0cHM6Ly9rdWJlcm5ldGVzLmRlZmF1bHQuc3ZjLmNsdXN0ZXIubG9jYWwiLCJrdWJlcm5ldGVzLmlvIjp7Im5hbWVzcGFjZSI6ImF1dGhvcmlubyIsInNlcnZpY2VhY2NvdW50Ijp7Im5hbWUiOiJhcGktY29uc3VtZXItMSIsInVpZCI6ImI0MGY1MzFjLWVjYWItNGYzMS1hNDk2LTJlYmM3MmFkZDEyMSJ9fSwibmJmIjoxNjM0ODMwNDUxLCJzdWIiOiJzeXN0ZW06c2VydmljZWFjY291bnQ6YXV0aG9yaW5vOmFwaS1jb25zdW1lci0xIn0.PaP0vqdl5DPfErr84KfVhPdlsGAPgsw0NkDaA9rne1zXjzcO7KPPbXhFwZC-oIjSGG1HfRMSoQeCXbQz24PSATmX8l1T52a9IFeXgP7sQmXZIDbiPfTm3X09kIIlfPKHhK_f-jQwRIpMRqNgLntlZ-xXX3P1fOBBUYR8obTPAQ6NDDaLHxw2SAmHFTQWjM_DInPDemXX0mEm7nCPKifsNxHaQH4wx4CD3LCLGbCI9FHNf2Crid8mmGJXf4wzcH1VuKkpUlsmnlUgTG2bfT2lbhSF2lBmrrhTJyYk6_aA09DwL4Bf4kvG-JtCq0Bkd_XynViIsOtOnAhgmdSPkfr-oA","user-agent":"curl/7.65.3","x-envoy-internal":"true","x-forwarded-for":"10.244.0.11","x-forwarded-proto":"http","x-request-id":"4c5d5c97-e15b-46a3-877a-d8188e09e08f"},"path":"/hello","host":"talker-api","scheme":"http","protocol":"HTTP/1.1"}},"context_extensions":{"virtual_host":"local_service"},"metadata_context":{}},"auth":{"identity":{"aud":["talker-api"],"exp":1634831051,"iat":1634830451,"iss":"https://kubernetes.default.svc.cluster.local","kubernetes.io":{"namespace":"authorino","serviceaccount":{"name":"api-consumer-1","uid":"b40f531c-ecab-4f31-a496-2ebc72add121"}},"nbf":1634830451,"sub":"system:serviceaccount:authorino:api-consumer-1"},"metadata":{"http-metadata":{"body":"","headers":{"Accept-Encoding":"gzip","Content-Type":"text/plain","Host":"talker-api.authorino.svc.cluster.local:3000","User-Agent":"Go-http-client/1.1","Version":"HTTP/1.1"},"method":"GET","path":"/metadata","query_string":"encoding=text/plain&original_path=/hello","uuid":"1aa6ac66-3179-4351-b1a7-7f6a761d5b61"},"uma-resource-registry":[{"_id":"e20d194c-274c-4845-8c02-0ca413c9bf18","attributes":{},"displayName":"hello","name":"hello","owner":{"id":"57a645a5-fb67-438b-8be5-dfb971666dbc"},"ownerManagedAccess":false,"resource_scopes":[],"uris":["/hi","/hello"]}]}}}} +{"level":"debug","ts":1634830460.2955465,"logger":"authorino.service.auth.authpipeline.authorization.kubernetesauthz","msg":"calling kubernetes subject access review api","request id":"8157480586935853928","subjectaccessreview":{"metadata":{"creationTimestamp":null},"spec":{"nonResourceAttributes":{"path":"/hello","verb":"get"},"user":"system:serviceaccount:authorino:api-consumer-1"},"status":{"allowed":false}}} +{"level":"debug","ts":1634830460.2986183,"logger":"authorino.service.auth.authpipeline.authorization","msg":"access granted","request id":"8157480586935853928","config":{"Name":"my-policy","OPA":{"Rego":"fail := input.context.request.http.headers[\"x-ext-auth-mock\"] == \"FAIL\"\nallow { not fail }\n","OPAExternalSource":{"Endpoint":"","SharedSecret":"","AuthCredentials":{"KeySelector":"Bearer","In":"authorization_header"}}},"JSON":null,"KubernetesAuthz":null},"object":true} +{"level":"debug","ts":1634830460.3044975,"logger":"authorino.service.auth.authpipeline.authorization","msg":"access granted","request id":"8157480586935853928","config":{"Name":"kubernetes-rbac","OPA":null,"JSON":null,"KubernetesAuthz":{"Conditions":[],"User":{"Static":"","Pattern":"auth.identity.sub"},"Groups":null,"ResourceAttributes":null}},"object":true} +{"level":"debug","ts":1634830460.3052874,"logger":"authorino.service.auth.authpipeline.response","msg":"dynamic response built","request id":"8157480586935853928","config":{"Name":"wristband","Wrapper":"httpHeader","WrapperKey":"x-ext-auth-wristband","Wristband":{"Issuer":"https://authorino-oidc.authorino.svc:8083/authorino/talker-api-protection/wristband","CustomClaims":[],"TokenDuration":300,"SigningKeys":[{"use":"sig","kty":"EC","kid":"wristband-signing-key","crv":"P-256","alg":"ES256","x":"TJf5NLVKplSYp95TOfhVPqvxvEibRyjrUZwwtpDuQZw","y":"SSg8rKBsJ3J1LxyLtt0oFvhHvZcUpmRoTuHk3UHisTA","d":"Me-5_zWBWVYajSGZcZMCcD8dXEa4fy85zv_yN7BxW-o"}]},"DynamicJSON":null},"object":"eyJhbGciOiJFUzI1NiIsImtpZCI6IndyaXN0YmFuZC1zaWduaW5nLWtleSIsInR5cCI6IkpXVCJ9.eyJleHAiOjE2MzQ4MzA3NjAsImlhdCI6MTYzNDgzMDQ2MCwiaXNzIjoiaHR0cHM6Ly9hdXRob3Jpbm8tb2lkYy5hdXRob3Jpbm8uc3ZjOjgwODMvYXV0aG9yaW5vL3RhbGtlci1hcGktcHJvdGVjdGlvbi93cmlzdGJhbmQiLCJzdWIiOiI4NDliMDk0ZDA4MzU0ZjM0MjA4ZGI3MjBmYWZmODlmNmM3NmYyOGY3MTcxOWI4NTQ3ZDk5NWNlNzAwMjU2ZGY4In0.Jn-VB5Q_0EX1ed1ji4KvhO4DlMqZeIl5H0qlukbTyYkp-Pgb4SnPGSbYWp5_uvG8xllsFAA5nuyBIXeba-dbkw"} +{"level":"info","ts":1634830460.3054585,"logger":"authorino.service.auth","msg":"outgoing authorization response","request id":"8157480586935853928","authorized":true,"response":"OK"} +{"level":"debug","ts":1634830460.305476,"logger":"authorino.service.auth","msg":"outgoing authorization response","request id":"8157480586935853928","authorized":true,"response":"OK"} +``` + +#### Enforcing `AuthConfig` while authenticating with API key: + +
+ AuhConfig composed of: + + - identity: k8s-auth, oidc, oauth2, apikey + - metadata: http, oidc userinfo + - authorization: opa, k8s-authz + - response: wristband +
+ +```jsonc +{"level":"info","ts":1634830413.2425854,"logger":"authorino.service.auth","msg":"incoming authorization request","request id":"7199257136822741594","object":{"source":{"address":{"Address":{"SocketAddress":{"address":"127.0.0.1","PortSpecifier":{"PortValue":52702}}}}},"destination":{"address":{"Address":{"SocketAddress":{"address":"127.0.0.1","PortSpecifier":{"PortValue":8000}}}}},"request":{"http":{"id":"7199257136822741594","method":"GET","path":"/hello","host":"talker-api","scheme":"http"}}}} +{"level":"debug","ts":1634830413.2426975,"logger":"authorino.service.auth","msg":"incoming authorization request","request id":"7199257136822741594","object":{"source":{"address":{"Address":{"SocketAddress":{"address":"127.0.0.1","PortSpecifier":{"PortValue":52702}}}}},"destination":{"address":{"Address":{"SocketAddress":{"address":"127.0.0.1","PortSpecifier":{"PortValue":8000}}}}},"request":{"time":{"seconds":1634830413,"nanos":240094000},"http":{"id":"7199257136822741594","method":"GET","headers":{":authority":"talker-api",":method":"GET",":path":"/hello",":scheme":"http","accept":"*/*","authorization":"APIKEY ndyBzreUzF4zqDQsqSPMHkRhriEOtcRx","user-agent":"curl/7.65.3","x-envoy-internal":"true","x-forwarded-for":"10.244.0.11","x-forwarded-proto":"http","x-request-id":"d38f5e66-bd72-4733-95d1-3179315cdd60"},"path":"/hello","host":"talker-api","scheme":"http","protocol":"HTTP/1.1"}},"context_extensions":{"virtual_host":"local_service"},"metadata_context":{}}} +{"level":"debug","ts":1634830413.2428744,"logger":"authorino.service.auth.authpipeline.identity","msg":"cannot validate identity","request id":"7199257136822741594","config":{"Name":"k8s-service-accounts","ExtendedProperties":[],"OAuth2":null,"OIDC":null,"MTLS":null,"HMAC":null,"APIKey":null,"KubernetesAuth":{"AuthCredentials":{"KeySelector":"Bearer","In":"authorization_header"}}},"reason":"credential not found"} +{"level":"debug","ts":1634830413.2434332,"logger":"authorino.service.auth.authpipeline","msg":"skipping config","request id":"7199257136822741594","config":{"Name":"keycloak-jwts","ExtendedProperties":[],"OAuth2":null,"OIDC":{"AuthCredentials":{"KeySelector":"Bearer","In":"authorization_header"},"Endpoint":"http://keycloak:8080/auth/realms/kuadrant"},"MTLS":null,"HMAC":null,"APIKey":null,"KubernetesAuth":null},"reason":"context canceled"} +{"level":"debug","ts":1634830413.2479305,"logger":"authorino.service.auth.authpipeline.identity","msg":"identity validated","request id":"7199257136822741594","config":{"Name":"api-keys","ExtendedProperties":[{"Name":"sub","Value":{"Static":null,"Pattern":"auth.identity.metadata.annotations.userid"}}],"OAuth2":null,"OIDC":null,"MTLS":null,"HMAC":null,"APIKey":{"AuthCredentials":{"KeySelector":"APIKEY","In":"authorization_header"},"Name":"api-keys","LabelSelectors":{"audience":"talker-api","authorino.3scale.net/managed-by":"authorino"}},"KubernetesAuth":null},"object":{"apiVersion":"v1","data":{"api_key":"bmR5QnpyZVV6RjR6cURRc3FTUE1Ia1JocmlFT3RjUng="},"kind":"Secret","metadata":{"annotations":{"kubectl.kubernetes.io/last-applied-configuration":"{\"apiVersion\":\"v1\",\"kind\":\"Secret\",\"metadata\":{\"annotations\":{\"userid\":\"john\"},\"labels\":{\"audience\":\"talker-api\",\"authorino.3scale.net/managed-by\":\"authorino\"},\"name\":\"api-key-1\",\"namespace\":\"authorino\"},\"stringData\":{\"api_key\":\"ndyBzreUzF4zqDQsqSPMHkRhriEOtcRx\"},\"type\":\"Opaque\"}\n","userid":"john"},"creationTimestamp":"2021-10-21T14:45:54Z","labels":{"audience":"talker-api","authorino.3scale.net/managed-by":"authorino"},"managedFields":[{"apiVersion":"v1","fieldsType":"FieldsV1","fieldsV1":{"f:data":{".":{},"f:api_key":{}},"f:metadata":{"f:annotations":{".":{},"f:kubectl.kubernetes.io/last-applied-configuration":{},"f:userid":{}},"f:labels":{".":{},"f:audience":{},"f:authorino.3scale.net/managed-by":{}}},"f:type":{}},"manager":"kubectl-client-side-apply","operation":"Update","time":"2021-10-21T14:45:54Z"}],"name":"api-key-1","namespace":"authorino","resourceVersion":"8979","uid":"c369852a-7e1a-43bd-94ca-e2b3f617052e"},"sub":"john","type":"Opaque"}} +{"level":"debug","ts":1634830413.248768,"logger":"authorino.service.auth.authpipeline.metadata.http","msg":"sending request","request id":"7199257136822741594","method":"GET","url":"http://talker-api.authorino.svc.cluster.local:3000/metadata?encoding=text/plain&original_path=/hello","headers":{"Content-Type":["text/plain"]}} +{"level":"debug","ts":1634830413.2496722,"logger":"authorino.service.auth.authpipeline.metadata","msg":"cannot fetch metadata","request id":"7199257136822741594","config":{"Name":"oidc-userinfo","UserInfo":{"OIDC":{"AuthCredentials":{"KeySelector":"Bearer","In":"authorization_header"},"Endpoint":"http://keycloak:8080/auth/realms/kuadrant"}},"UMA":null,"GenericHTTP":null},"reason":"Missing identity for OIDC issuer http://keycloak:8080/auth/realms/kuadrant. Skipping related UserInfo metadata."} +{"level":"debug","ts":1634830413.2497928,"logger":"authorino.service.auth.authpipeline.metadata.uma","msg":"requesting pat","request id":"7199257136822741594","url":"http://talker-api:523b92b6-625d-4e1e-a313-77e7a8ae4e88@keycloak:8080/auth/realms/kuadrant/protocol/openid-connect/token","data":"grant_type=client_credentials","headers":{"Content-Type":["application/x-www-form-urlencoded"]}} +{"level":"debug","ts":1634830413.258932,"logger":"authorino.service.auth.authpipeline.metadata","msg":"fetched auth metadata","request id":"7199257136822741594","config":{"Name":"http-metadata","UserInfo":null,"UMA":null,"GenericHTTP":{"Endpoint":"http://talker-api.authorino.svc.cluster.local:3000/metadata?encoding=text/plain&original_path={context.request.http.path}","Method":"GET","Parameters":[],"ContentType":"application/x-www-form-urlencoded","SharedSecret":"","AuthCredentials":{"KeySelector":"Bearer","In":"authorization_header"}}},"object":{"body":"","headers":{"Accept-Encoding":"gzip","Content-Type":"text/plain","Host":"talker-api.authorino.svc.cluster.local:3000","User-Agent":"Go-http-client/1.1","Version":"HTTP/1.1"},"method":"GET","path":"/metadata","query_string":"encoding=text/plain&original_path=/hello","uuid":"97529f8c-587b-4121-a4db-cd90c63871fd"}} +{"level":"debug","ts":1634830413.2945344,"logger":"authorino.service.auth.authpipeline.metadata.uma","msg":"querying resources by uri","request id":"7199257136822741594","url":"http://keycloak:8080/auth/realms/kuadrant/authz/protection/resource_set?uri=/hello"} +{"level":"debug","ts":1634830413.3123596,"logger":"authorino.service.auth.authpipeline.metadata.uma","msg":"getting resource data","request id":"7199257136822741594","url":"http://keycloak:8080/auth/realms/kuadrant/authz/protection/resource_set/e20d194c-274c-4845-8c02-0ca413c9bf18"} +{"level":"debug","ts":1634830413.3340268,"logger":"authorino.service.auth.authpipeline.metadata","msg":"fetched auth metadata","request id":"7199257136822741594","config":{"Name":"uma-resource-registry","UserInfo":null,"UMA":{"Endpoint":"http://keycloak:8080/auth/realms/kuadrant","ClientID":"talker-api","ClientSecret":"523b92b6-625d-4e1e-a313-77e7a8ae4e88"},"GenericHTTP":null},"object":[{"_id":"e20d194c-274c-4845-8c02-0ca413c9bf18","attributes":{},"displayName":"hello","name":"hello","owner":{"id":"57a645a5-fb67-438b-8be5-dfb971666dbc"},"ownerManagedAccess":false,"resource_scopes":[],"uris":["/hi","/hello"]}]} +{"level":"debug","ts":1634830413.3367748,"logger":"authorino.service.auth.authpipeline.authorization","msg":"evaluating for input","request id":"7199257136822741594","input":{"context":{"source":{"address":{"Address":{"SocketAddress":{"address":"127.0.0.1","PortSpecifier":{"PortValue":52702}}}}},"destination":{"address":{"Address":{"SocketAddress":{"address":"127.0.0.1","PortSpecifier":{"PortValue":8000}}}}},"request":{"time":{"seconds":1634830413,"nanos":240094000},"http":{"id":"7199257136822741594","method":"GET","headers":{":authority":"talker-api",":method":"GET",":path":"/hello",":scheme":"http","accept":"*/*","authorization":"APIKEY ndyBzreUzF4zqDQsqSPMHkRhriEOtcRx","user-agent":"curl/7.65.3","x-envoy-internal":"true","x-forwarded-for":"10.244.0.11","x-forwarded-proto":"http","x-request-id":"d38f5e66-bd72-4733-95d1-3179315cdd60"},"path":"/hello","host":"talker-api","scheme":"http","protocol":"HTTP/1.1"}},"context_extensions":{"virtual_host":"local_service"},"metadata_context":{}},"auth":{"identity":{"apiVersion":"v1","data":{"api_key":"bmR5QnpyZVV6RjR6cURRc3FTUE1Ia1JocmlFT3RjUng="},"kind":"Secret","metadata":{"annotations":{"kubectl.kubernetes.io/last-applied-configuration":"{\"apiVersion\":\"v1\",\"kind\":\"Secret\",\"metadata\":{\"annotations\":{\"userid\":\"john\"},\"labels\":{\"audience\":\"talker-api\",\"authorino.3scale.net/managed-by\":\"authorino\"},\"name\":\"api-key-1\",\"namespace\":\"authorino\"},\"stringData\":{\"api_key\":\"ndyBzreUzF4zqDQsqSPMHkRhriEOtcRx\"},\"type\":\"Opaque\"}\n","userid":"john"},"creationTimestamp":"2021-10-21T14:45:54Z","labels":{"audience":"talker-api","authorino.3scale.net/managed-by":"authorino"},"managedFields":[{"apiVersion":"v1","fieldsType":"FieldsV1","fieldsV1":{"f:data":{".":{},"f:api_key":{}},"f:metadata":{"f:annotations":{".":{},"f:kubectl.kubernetes.io/last-applied-configuration":{},"f:userid":{}},"f:labels":{".":{},"f:audience":{},"f:authorino.3scale.net/managed-by":{}}},"f:type":{}},"manager":"kubectl-client-side-apply","operation":"Update","time":"2021-10-21T14:45:54Z"}],"name":"api-key-1","namespace":"authorino","resourceVersion":"8979","uid":"c369852a-7e1a-43bd-94ca-e2b3f617052e"},"sub":"john","type":"Opaque"},"metadata":{"http-metadata":{"body":"","headers":{"Accept-Encoding":"gzip","Content-Type":"text/plain","Host":"talker-api.authorino.svc.cluster.local:3000","User-Agent":"Go-http-client/1.1","Version":"HTTP/1.1"},"method":"GET","path":"/metadata","query_string":"encoding=text/plain&original_path=/hello","uuid":"97529f8c-587b-4121-a4db-cd90c63871fd"},"uma-resource-registry":[{"_id":"e20d194c-274c-4845-8c02-0ca413c9bf18","attributes":{},"displayName":"hello","name":"hello","owner":{"id":"57a645a5-fb67-438b-8be5-dfb971666dbc"},"ownerManagedAccess":false,"resource_scopes":[],"uris":["/hi","/hello"]}]}}}} +{"level":"debug","ts":1634830413.339894,"logger":"authorino.service.auth.authpipeline.authorization","msg":"access granted","request id":"7199257136822741594","config":{"Name":"my-policy","OPA":{"Rego":"fail := input.context.request.http.headers[\"x-ext-auth-mock\"] == \"FAIL\"\nallow { not fail }\n","OPAExternalSource":{"Endpoint":"","SharedSecret":"","AuthCredentials":{"KeySelector":"Bearer","In":"authorization_header"}}},"JSON":null,"KubernetesAuthz":null},"object":true} +{"level":"debug","ts":1634830413.3444238,"logger":"authorino.service.auth.authpipeline.authorization.kubernetesauthz","msg":"calling kubernetes subject access review api","request id":"7199257136822741594","subjectaccessreview":{"metadata":{"creationTimestamp":null},"spec":{"nonResourceAttributes":{"path":"/hello","verb":"get"},"user":"john"},"status":{"allowed":false}}} +{"level":"debug","ts":1634830413.3547812,"logger":"authorino.service.auth.authpipeline.authorization","msg":"access granted","request id":"7199257136822741594","config":{"Name":"kubernetes-rbac","OPA":null,"JSON":null,"KubernetesAuthz":{"Conditions":[],"User":{"Static":"","Pattern":"auth.identity.sub"},"Groups":null,"ResourceAttributes":null}},"object":true} +{"level":"debug","ts":1634830413.3558292,"logger":"authorino.service.auth.authpipeline.response","msg":"dynamic response built","request id":"7199257136822741594","config":{"Name":"wristband","Wrapper":"httpHeader","WrapperKey":"x-ext-auth-wristband","Wristband":{"Issuer":"https://authorino-oidc.authorino.svc:8083/authorino/talker-api-protection/wristband","CustomClaims":[],"TokenDuration":300,"SigningKeys":[{"use":"sig","kty":"EC","kid":"wristband-signing-key","crv":"P-256","alg":"ES256","x":"TJf5NLVKplSYp95TOfhVPqvxvEibRyjrUZwwtpDuQZw","y":"SSg8rKBsJ3J1LxyLtt0oFvhHvZcUpmRoTuHk3UHisTA","d":"Me-5_zWBWVYajSGZcZMCcD8dXEa4fy85zv_yN7BxW-o"}]},"DynamicJSON":null},"object":"eyJhbGciOiJFUzI1NiIsImtpZCI6IndyaXN0YmFuZC1zaWduaW5nLWtleSIsInR5cCI6IkpXVCJ9.eyJleHAiOjE2MzQ4MzA3MTMsImlhdCI6MTYzNDgzMDQxMywiaXNzIjoiaHR0cHM6Ly9hdXRob3Jpbm8tb2lkYy5hdXRob3Jpbm8uc3ZjOjgwODMvYXV0aG9yaW5vL3RhbGtlci1hcGktcHJvdGVjdGlvbi93cmlzdGJhbmQiLCJzdWIiOiI5NjhiZjViZjk3MDM3NWRiNjE0ZDFhMDgzZTg2NTBhYTVhMGVhMzAyOTdiYmJjMTBlNWVlMWZmYTkxYTYwZmY4In0.7G440sWgi2TIaxrGJf5KWR9UOFpNTjwVYeaJXFLzsLhVNICoMLbYzBAEo4M3ym1jipxxTVeE7anm4qDDc7cnVQ"} +{"level":"info","ts":1634830413.3569078,"logger":"authorino.service.auth","msg":"outgoing authorization response","request id":"7199257136822741594","authorized":true,"response":"OK"} +{"level":"debug","ts":1634830413.3569596,"logger":"authorino.service.auth","msg":"outgoing authorization response","request id":"7199257136822741594","authorized":true,"response":"OK"} +``` + +#### Enforcing `AuthConfig` while authenticating with invalid API key: + +
+ AuhConfig composed of: + + - identity: k8s-auth, oidc, oauth2, apikey + - metadata: http, oidc userinfo + - authorization: opa, k8s-authz + - response: wristband +
+ +```jsonc +{"level":"info","ts":1634830373.2066543,"logger":"authorino.service.auth","msg":"incoming authorization request","request id":"12947265773116138711","object":{"source":{"address":{"Address":{"SocketAddress":{"address":"127.0.0.1","PortSpecifier":{"PortValue":52288}}}}},"destination":{"address":{"Address":{"SocketAddress":{"address":"127.0.0.1","PortSpecifier":{"PortValue":8000}}}}},"request":{"http":{"id":"12947265773116138711","method":"GET","path":"/hello","host":"talker-api","scheme":"http"}}}} +{"level":"debug","ts":1634830373.2068064,"logger":"authorino.service.auth","msg":"incoming authorization request","request id":"12947265773116138711","object":{"source":{"address":{"Address":{"SocketAddress":{"address":"127.0.0.1","PortSpecifier":{"PortValue":52288}}}}},"destination":{"address":{"Address":{"SocketAddress":{"address":"127.0.0.1","PortSpecifier":{"PortValue":8000}}}}},"request":{"time":{"seconds":1634830373,"nanos":198329000},"http":{"id":"12947265773116138711","method":"GET","headers":{":authority":"talker-api",":method":"GET",":path":"/hello",":scheme":"http","accept":"*/*","authorization":"APIKEY invalid","user-agent":"curl/7.65.3","x-envoy-internal":"true","x-forwarded-for":"10.244.0.11","x-forwarded-proto":"http","x-request-id":"9e391846-afe4-489a-8716-23a2e1c1aa77"},"path":"/hello","host":"talker-api","scheme":"http","protocol":"HTTP/1.1"}},"context_extensions":{"virtual_host":"local_service"},"metadata_context":{}}} +{"level":"debug","ts":1634830373.2070816,"logger":"authorino.service.auth.authpipeline.identity","msg":"cannot validate identity","request id":"12947265773116138711","config":{"Name":"keycloak-opaque","ExtendedProperties":[],"OAuth2":{"AuthCredentials":{"KeySelector":"Bearer","In":"authorization_header"},"TokenIntrospectionUrl":"http://keycloak:8080/auth/realms/kuadrant/protocol/openid-connect/token/introspect","TokenTypeHint":"requesting_party_token","ClientID":"talker-api","ClientSecret":"523b92b6-625d-4e1e-a313-77e7a8ae4e88"},"OIDC":null,"MTLS":null,"HMAC":null,"APIKey":null,"KubernetesAuth":null},"reason":"credential not found"} +{"level":"debug","ts":1634830373.207225,"logger":"authorino.service.auth.authpipeline.identity","msg":"cannot validate identity","request id":"12947265773116138711","config":{"Name":"api-keys","ExtendedProperties":[{"Name":"sub","Value":{"Static":null,"Pattern":"auth.identity.metadata.annotations.userid"}}],"OAuth2":null,"OIDC":null,"MTLS":null,"HMAC":null,"APIKey":{"AuthCredentials":{"KeySelector":"APIKEY","In":"authorization_header"},"Name":"api-keys","LabelSelectors":{"audience":"talker-api","authorino.3scale.net/managed-by":"authorino"}},"KubernetesAuth":null},"reason":"the API Key provided is invalid"} +{"level":"debug","ts":1634830373.2072473,"logger":"authorino.service.auth.authpipeline.identity","msg":"cannot validate identity","request id":"12947265773116138711","config":{"Name":"k8s-service-accounts","ExtendedProperties":[],"OAuth2":null,"OIDC":null,"MTLS":null,"HMAC":null,"APIKey":null,"KubernetesAuth":{"AuthCredentials":{"KeySelector":"Bearer","In":"authorization_header"}}},"reason":"credential not found"} +{"level":"debug","ts":1634830373.2072592,"logger":"authorino.service.auth.authpipeline.identity","msg":"cannot validate identity","request id":"12947265773116138711","config":{"Name":"keycloak-jwts","ExtendedProperties":[],"OAuth2":null,"OIDC":{"AuthCredentials":{"KeySelector":"Bearer","In":"authorization_header"},"Endpoint":"http://keycloak:8080/auth/realms/kuadrant"},"MTLS":null,"HMAC":null,"APIKey":null,"KubernetesAuth":null},"reason":"credential not found"} +{"level":"info","ts":1634830373.2073083,"logger":"authorino.service.auth","msg":"outgoing authorization response","request id":"12947265773116138711","authorized":false,"response":"UNAUTHENTICATED","object":{"code":16,"status":302,"message":"Redirecting to login"}} +{"level":"debug","ts":1634830373.2073889,"logger":"authorino.service.auth","msg":"outgoing authorization response","request id":"12947265773116138711","authorized":false,"response":"UNAUTHENTICATED","object":{"code":16,"status":302,"message":"Redirecting to login","headers":[{"Location":"https://my-app.io/login"}]}} +``` + +#### Deleting `AuthConfig` and related API key `Secret`s: + +```jsonc +{"level":"info","ts":1634675366.8794427,"logger":"authorino.controller-runtime.manager.controller.authconfig","msg":"object has been deleted, deleted related configs","authconfig":"authorino/talker-api-protection"} +{"level":"info","ts":1634675366.9552257,"logger":"authorino.controller-runtime.manager.controller.secret","msg":"resource reconciled","secret":"authorino/api-key-1"} +{"level":"info","ts":1634675366.9749846,"logger":"authorino.controller-runtime.manager.controller.secret","msg":"resource reconciled","secret":"authorino/api-key-2"} +``` + +#### Shutting down the service: + +```jsonc +{"level":"info","ts":1634675390.0908618,"logger":"authorino.controller-runtime.manager.controller.authconfig","msg":"Shutdown signal received, waiting for all workers to finish","reconciler group":"authorino.3scale.net","reconciler kind":"AuthConfig"} +{"level":"info","ts":1634675390.0909622,"logger":"authorino.controller-runtime.manager.controller.secret","msg":"Shutdown signal received, waiting for all workers to finish","reconciler group":"","reconciler kind":"Secret"} +{"level":"info","ts":1634675390.0968425,"logger":"authorino.controller-runtime.manager.controller.authconfig","msg":"Shutdown signal received, waiting for all workers to finish","reconciler group":"authorino.3scale.net","reconciler kind":"AuthConfig"} +{"level":"info","ts":1634675390.101609,"logger":"authorino.controller-runtime.manager.controller.secret","msg":"All workers finished","reconciler group":"","reconciler kind":"Secret"} +{"level":"info","ts":1634675390.10166,"logger":"authorino.controller-runtime.manager.controller.authconfig","msg":"All workers finished","reconciler group":"authorino.3scale.net","reconciler kind":"AuthConfig"} +{"level":"info","ts":1634675390.1017516,"logger":"authorino.controller-runtime.manager.controller.authconfig","msg":"All workers finished","reconciler group":"authorino.3scale.net","reconciler kind":"AuthConfig"} +``` diff --git a/go.mod b/go.mod index 287d81b5..701c031c 100644 --- a/go.mod +++ b/go.mod @@ -14,6 +14,7 @@ require ( github.com/open-policy-agent/opa v0.25.2 github.com/pquerna/cachecontrol v0.0.0-20201205024021-ac21108117ac // indirect github.com/tidwall/gjson v1.6.8 + go.uber.org/zap v1.17.0 golang.org/x/net v0.0.0-20210428140749-89ef3d95e781 google.golang.org/genproto v0.0.0-20201110150050-8816d57aaa9a google.golang.org/grpc v1.27.1 @@ -23,5 +24,6 @@ require ( k8s.io/api v0.21.2 k8s.io/apimachinery v0.21.2 k8s.io/client-go v0.21.2 + k8s.io/klog/v2 v2.8.0 sigs.k8s.io/controller-runtime v0.9.2 ) diff --git a/main.go b/main.go index e71341ad..653f8d24 100644 --- a/main.go +++ b/main.go @@ -32,6 +32,7 @@ import ( "github.com/kuadrant/authorino/controllers" "github.com/kuadrant/authorino/pkg/cache" "github.com/kuadrant/authorino/pkg/common" + "github.com/kuadrant/authorino/pkg/common/log" "github.com/kuadrant/authorino/pkg/service" "k8s.io/apimachinery/pkg/runtime" @@ -39,7 +40,6 @@ import ( clientgoscheme "k8s.io/client-go/kubernetes/scheme" _ "k8s.io/client-go/plugin/pkg/client/auth/gcp" ctrl "sigs.k8s.io/controller-runtime" - "sigs.k8s.io/controller-runtime/pkg/log/zap" // +kubebuilder:scaffold:imports ) @@ -49,11 +49,12 @@ const ( ) var ( - scheme = runtime.NewScheme() - setupLog = ctrl.Log.WithName("setup") + scheme = runtime.NewScheme() watchNamespace = common.FetchEnv("WATCH_NAMESPACE", "") authorinoWatchedSecretLabel = common.FetchEnv("AUTHORINO_SECRET_LABEL_KEY", defaultAuthorinoWatchedSecretLabel) + logLevel = common.FetchEnv("LOG_LEVEL", "info") + logMode = common.FetchEnv("LOG_MODE", "production") extAuthGRPCPort = common.FetchEnv("EXT_AUTH_GRPC_PORT", "50051") tlsCertPath = common.FetchEnv("TLS_CERT", "") @@ -62,6 +63,8 @@ var ( oidcHTTPPort = common.FetchEnv("OIDC_HTTP_PORT", "8083") oidcTLSCertPath = common.FetchEnv("OIDC_TLS_CERT", "") oidcTLSCertKeyPath = common.FetchEnv("OIDC_TLS_CERT_KEY", "") + + logger = log.NewLogger(log.Options{Level: log.ToLogLevel(logLevel), Mode: log.ToLogMode(logMode)}, nil).WithName("authorino") ) func init() { @@ -69,6 +72,8 @@ func init() { utilruntime.Must(configv1beta1.AddToScheme(scheme)) // +kubebuilder:scaffold:scheme + + log.SetLogger(logger) } func main() { @@ -80,8 +85,6 @@ func main() { "Enabling this will ensure there is only one active controller manager.") flag.Parse() - ctrl.SetLogger(zap.New(zap.UseDevMode(true))) - managerOptions := ctrl.Options{ Scheme: scheme, MetricsBindAddress: metricsAddr, @@ -94,35 +97,35 @@ func main() { } mgr, err := ctrl.NewManager(ctrl.GetConfigOrDie(), managerOptions) - if err != nil { - setupLog.Error(err, "unable to start manager") + logger.Error(err, "unable to start manager") os.Exit(1) } cache := cache.NewCache() + controllerLogger := log.WithName("controller-runtime").WithName("manager").WithName("controller") // sets up the auth config reconciler authConfigReconciler := &controllers.AuthConfigReconciler{ Client: mgr.GetClient(), Cache: cache, - Log: ctrl.Log.WithName("authorino").WithName("controller").WithName("AuthConfig"), + Logger: controllerLogger.WithName("authconfig"), Scheme: mgr.GetScheme(), } if err = authConfigReconciler.SetupWithManager(mgr); err != nil { - setupLog.Error(err, "unable to create controller", "controller", "AuthConfig") + logger.Error(err, "unable to create controller", "controller", "authconfig") os.Exit(1) } // sets up secret reconciler if err = (&controllers.SecretReconciler{ Client: mgr.GetClient(), - Log: ctrl.Log.WithName("authorino").WithName("controller").WithName("Secret"), + Logger: controllerLogger.WithName("secret"), Scheme: mgr.GetScheme(), SecretLabel: authorinoWatchedSecretLabel, AuthConfigReconciler: authConfigReconciler, }).SetupWithManager(mgr); err != nil { - setupLog.Error(err, "unable to create controller", "controller", "Secret") + logger.Error(err, "unable to create controller", "controller", "secret") os.Exit(1) } @@ -133,11 +136,11 @@ func main() { signalHandler := ctrl.SetupSignalHandler() - setupLog.Info("Starting manager") + logger.Info("starting manager") go func() { if err := mgr.Start(signalHandler); err != nil { - setupLog.Error(err, "problem running manager") + logger.Error(err, "problem running manager") os.Exit(1) } }() @@ -148,21 +151,22 @@ func main() { managerOptions.MetricsBindAddress = "0" statusUpdateManager, err := ctrl.NewManager(ctrl.GetConfigOrDie(), managerOptions) if err != nil { - setupLog.Error(err, "unable to create status update manager") + logger.Error(err, "unable to start status update manager") os.Exit(1) } // sets up auth config status update controller if err = (&controllers.AuthConfigStatusUpdater{ Client: statusUpdateManager.GetClient(), + Logger: controllerLogger.WithName("authconfig").WithName("statusupdater"), }).SetupWithManager(statusUpdateManager); err != nil { - setupLog.Error(err, "unable to create controller", "controller", "AuthConfigStatusUpdate") + logger.Error(err, "unable to create controller", "controller", "authconfigstatusupdate") } - setupLog.Info("Starting status update manager") + logger.Info("starting status update manager") if err := statusUpdateManager.Start(signalHandler); err != nil { - setupLog.Error(err, "problem running status update manager") + logger.Error(err, "problem running status update manager") os.Exit(1) } } @@ -173,8 +177,6 @@ func startExtAuthServer(authConfigCache cache.Cache) { } func startExtAuthServerGRPC(authConfigCache cache.Cache) { - logger := ctrl.Log.WithName("authorino").WithName("auth") - if lis, err := net.Listen("tcp", ":"+extAuthGRPCPort); err != nil { logger.Error(err, "failed to obtain port for grpc auth service") os.Exit(1) @@ -216,8 +218,6 @@ func startExtAuthServerHTTP(authConfigCache cache.Cache) { } func startOIDCServer(authConfigCache cache.Cache) { - logger := ctrl.Log.WithName("authorino").WithName("oidc") - if lis, err := net.Listen("tcp", ":"+oidcHTTPPort); err != nil { logger.Error(err, "failed to obtain port for http oidc service") os.Exit(1) diff --git a/pkg/cache/cache_test.go b/pkg/cache/cache_test.go index 176c491a..4cccf2b9 100644 --- a/pkg/cache/cache_test.go +++ b/pkg/cache/cache_test.go @@ -13,7 +13,7 @@ import ( type BogusIdentity struct{} -func (f *BogusIdentity) Call(pipeline common.AuthPipeline, ctx context.Context) (interface{}, error) { +func (f *BogusIdentity) Call(_ common.AuthPipeline, _ context.Context) (interface{}, error) { return true, nil } diff --git a/pkg/common/auth.go b/pkg/common/auth.go index dfef7ada..8c6a6c6d 100644 --- a/pkg/common/auth.go +++ b/pkg/common/auth.go @@ -6,12 +6,14 @@ import ( "github.com/kuadrant/authorino/pkg/common/auth_credentials" envoy_auth "github.com/envoyproxy/go-control-plane/envoy/service/auth/v3" + envoy_type "github.com/envoyproxy/go-control-plane/envoy/type/v3" + "github.com/gogo/googleapis/google/rpc" v1 "k8s.io/api/core/v1" "k8s.io/apimachinery/pkg/types" ) type AuthPipeline interface { - GetParentContext() *context.Context + Evaluate() AuthResult GetRequest() *envoy_auth.CheckRequest GetHttp() *envoy_auth.AttributeContext_HttpRequest GetAPI() interface{} @@ -51,3 +53,25 @@ type ResponseConfigEvaluator interface { NamedConfigEvaluator GetWristbandIssuer() WristbandIssuer } + +// AuthResult holds the result data for building the response to an auth check +type AuthResult struct { + // Code is gRPC response code to the auth check + Code rpc.Code `json:"code,omitempty"` + // Status is HTTP status code to override the default mapping between gRPC response codes and HTTP status messages + // for auth + Status envoy_type.StatusCode `json:"status,omitempty"` + // Message is X-Ext-Auth-Reason message returned in an injected HTTP response header, to explain the reason of the + // auth check result + Message string `json:"message,omitempty"` + // Headers are other HTTP headers to inject in the response + Headers []map[string]string `json:"headers,omitempty"` + // Metadata are Envoy dynamic metadata content + Metadata map[string]interface{} `json:"metadata,omitempty"` +} + +// Success tells whether the auth check result was successful and therefore access can be granted to the requested +// resource or it has failed (deny access) +func (result *AuthResult) Success() bool { + return result.Code == rpc.OK +} diff --git a/pkg/common/auth_credentials/auth_credentials.go b/pkg/common/auth_credentials/auth_credentials.go index fdb6b8bd..5e415f14 100644 --- a/pkg/common/auth_credentials/auth_credentials.go +++ b/pkg/common/auth_credentials/auth_credentials.go @@ -8,8 +8,9 @@ import ( "regexp" "strings" + "github.com/kuadrant/authorino/pkg/common/log" + envoyServiceAuthV3 "github.com/envoyproxy/go-control-plane/envoy/service/auth/v3" - ctrl "sigs.k8s.io/controller-runtime" ) // AuthCredentials interface represents the methods needed to fetch credentials from input @@ -42,7 +43,8 @@ const ( ) var ( - authCredLog = ctrl.Log.WithName("Authorino").WithName("AuthCredential") + logger = log.WithName("authcredential").V(1) + notFoundErr = fmt.Errorf(credentialNotFoundMsg) ) @@ -129,7 +131,7 @@ func (c *AuthCredential) BuildRequestWithCredentials(ctx context.Context, endpoi func getCredFromCustomHeader(headers map[string]string, keyName string) (string, error) { cred, ok := headers[strings.ToLower(keyName)] if !ok { - authCredLog.Error(notFoundErr, credentialNotFoundInHeaderMsg) + logger.Error(notFoundErr, credentialNotFoundInHeaderMsg) return "", notFoundErr } return cred, nil @@ -139,7 +141,7 @@ func getCredFromAuthHeader(headers map[string]string, keyName string) (string, e authHeader, ok := headers["authorization"] if !ok { - authCredLog.Error(notFoundErr, authHeaderNotSetMsg) + logger.Error(notFoundErr, authHeaderNotSetMsg) return "", notFoundErr } prefix := keyName + " " @@ -152,7 +154,7 @@ func getCredFromAuthHeader(headers map[string]string, keyName string) (string, e func getFromCookieHeader(headers map[string]string, keyName string) (string, error) { header, ok := headers["cookie"] if !ok { - authCredLog.Error(notFoundErr, cookieHeaderNotSetMsg) + logger.Error(notFoundErr, cookieHeaderNotSetMsg) return "", notFoundErr } diff --git a/pkg/common/log/log.go b/pkg/common/log/log.go new file mode 100644 index 00000000..e44d8903 --- /dev/null +++ b/pkg/common/log/log.go @@ -0,0 +1,182 @@ +package log + +import ( + "context" + "strings" + + "github.com/go-logr/logr" + "go.uber.org/zap/zapcore" + "k8s.io/klog/v2" + ctrl "sigs.k8s.io/controller-runtime" + "sigs.k8s.io/controller-runtime/pkg/log/zap" +) + +var ( + // Log is a singleton base logger that can be used across the system, + // either directly or to create other loggers with name, with values, + // and/or locked to a given log level. + // It is initialized to the promise delegation log provided by + // sigs.k8s.io/controller-runtime, which points to a no-op (null) logger + // until `SetLogger` is called. + // This is also useful for mocking the default logger tests. + Log logr.Logger = ctrl.Log +) + +type Logger = logr.Logger + +type LogLevel zapcore.Level + +func (l *LogLevel) String() string { + return zapcore.Level(*l).String() +} + +// ToLogLevel converts a string to a log level. +func ToLogLevel(level string) LogLevel { + var l zapcore.Level + _ = l.UnmarshalText([]byte(level)) + return LogLevel(l) +} + +// LogMode defines the log output mode. +type LogMode int8 + +const ( + // LogModeProd is the log mode for production. + LogModeProd LogMode = iota + // LogModeDev is for more human-readable outputs, extra stack traces + // and logging info. (aka Zap's "development config".) + LogModeDev +) + +func (f *LogMode) String() string { + switch *f { + case LogModeProd: + return "production" + case LogModeDev: + return "development" + default: + return "unknown" + } +} + +// ToLogMode converts a string to a log mode. +// Use either 'production' for `LogModeProd` or 'development' for `LogModeDev`. +func ToLogMode(mode string) LogMode { + switch strings.ToLower(mode) { + case "production": + return LogModeProd + case "development": + return LogModeDev + default: + panic("unknown log mode") + } +} + +// Options is a set of options for a configured logger. +type Options struct { + Level LogLevel + Mode LogMode +} + +// SetLogger sets up a logger. +func SetLogger(logger logr.Logger) { + opts := extractOptions(logger) + + Log = logger + + ctrl.SetLogger(logger) // fulfills `logger` as the de facto logger used by controller-runtime + klog.SetLogger(logger) + + logger.Info("setting instance base logger", "min level", opts.Level.String(), "mode", opts.Mode.String()) +} + +// WithName uses the singleton logger to create a new logger with the given name. +func WithName(name string) logr.Logger { + return Log.WithName(name) +} + +// WithName uses the singleton logger to create a new logger with the given values. +func WithValues(keysAndValues ...interface{}) logr.Logger { + return Log.WithValues(keysAndValues...) +} + +// V uses the singleton logger to create a new logger for the given log level. +func V(level int) logr.Logger { + return Log.V(level) +} + +// IntoContext takes a context and sets the logger as one of its values. +// Use FromContext function to retrieve the logger. +func IntoContext(ctx context.Context, log logr.Logger) context.Context { + return logr.NewContext(ctx, log) +} + +// FromContext returns a logger with predefined values from a context.Context. +func FromContext(ctx context.Context, keysAndValues ...interface{}) logr.Logger { + var log logr.Logger = Log + if ctx != nil { + if logger := logr.FromContext(ctx); logger != nil { + log = logger + } + } + return log.WithValues(keysAndValues...) +} + +// NewLogger returns a new logger with the given options. +// `logger` param is the actual logger implementation; when omitted, a new +// logger based on sigs.k8s.io/controller-runtime/pkg/log/zap is created. +func NewLogger(opts Options, logger logr.Logger) logr.Logger { + l := &configuredLogger{Options: opts} + + if logger != nil { + l.Logger = logger + } else { + l.Logger = zap.New( + zap.Level(zapcore.Level(opts.Level)), + zap.UseDevMode(opts.Mode == LogModeDev), + ) + } + + return l +} + +// configuredLogger is a delegation logger that holds information about the log options. +type configuredLogger struct { + Options Options + Logger logr.Logger +} + +func (l *configuredLogger) Enabled() bool { + return l.Logger.Enabled() +} + +func (l *configuredLogger) Info(msg string, keysAndValues ...interface{}) { + l.Logger.Info(msg, keysAndValues...) +} + +func (l *configuredLogger) Error(err error, msg string, keysAndValues ...interface{}) { + l.Logger.Error(err, msg, keysAndValues...) +} + +func (l *configuredLogger) V(level int) logr.Logger { + return NewLogger(l.Options, l.Logger.V(level)) +} + +func (l *configuredLogger) WithValues(keysAndValues ...interface{}) logr.Logger { + return NewLogger(l.Options, l.Logger.WithValues(keysAndValues...)) +} + +func (l *configuredLogger) WithName(name string) logr.Logger { + return NewLogger(l.Options, l.Logger.WithName(name)) +} + +func extractOptions(l logr.Logger) Options { + if cl, ok := l.(*configuredLogger); ok { + return cl.Options + } else { + return Options{ + Level: LogLevel(zapcore.InfoLevel), + Mode: LogModeProd, + } + } +} diff --git a/pkg/common/log/log_test.go b/pkg/common/log/log_test.go new file mode 100644 index 00000000..6ffef1c1 --- /dev/null +++ b/pkg/common/log/log_test.go @@ -0,0 +1,104 @@ +package log + +import ( + "testing" + + mock_logr "github.com/kuadrant/authorino/pkg/common/log/mocks" + + gomock "github.com/golang/mock/gomock" + "gotest.tools/assert" + ctrl "sigs.k8s.io/controller-runtime" +) + +func TestLogLevelToString(t *testing.T) { + level := LogLevel(-1) + assert.Equal(t, level.String(), "debug") + + level = LogLevel(0) + assert.Equal(t, level.String(), "info") + + level = LogLevel(1) + assert.Equal(t, level.String(), "warn") + + level = LogLevel(2) + assert.Equal(t, level.String(), "error") + + level = LogLevel(3) + assert.Equal(t, level.String(), "dpanic") + + level = LogLevel(4) + assert.Equal(t, level.String(), "panic") + + level = LogLevel(5) + assert.Equal(t, level.String(), "fatal") +} + +func TestToLogLevel(t *testing.T) { + assert.Equal(t, int(ToLogLevel("debug")), -1) + assert.Equal(t, int(ToLogLevel("info")), 0) + assert.Equal(t, int(ToLogLevel("warn")), 1) + assert.Equal(t, int(ToLogLevel("error")), 2) + assert.Equal(t, int(ToLogLevel("dpanic")), 3) + assert.Equal(t, int(ToLogLevel("panic")), 4) + assert.Equal(t, int(ToLogLevel("fatal")), 5) + assert.Equal(t, int(ToLogLevel("invalid")), 0) // falls back to default log level (info) without panicing +} + +func TestLogModeToString(t *testing.T) { + level := LogMode(0) + assert.Equal(t, level.String(), "production") + + level = LogMode(1) + assert.Equal(t, level.String(), "development") +} + +func TestToLogMode(t *testing.T) { + assert.Equal(t, int(ToLogMode("production")), 0) + assert.Equal(t, int(ToLogMode("development")), 1) + + defer func() { + if r := recover(); r == nil { + t.Errorf(`ToLogMode("invalid") was expected to panic and it did not.`) + } + }() + _ = ToLogMode("invalid") +} + +func TestWithName(t *testing.T) { + mockController := gomock.NewController(t) + defer func() { + mockController.Finish() + Log = ctrl.Log + }() + loggerMock := mock_logr.NewMockLogger(mockController) + Log = loggerMock + + loggerMock.EXPECT().WithName("test").Return(loggerMock) + WithName("test") +} + +func TestWithValues(t *testing.T) { + mockController := gomock.NewController(t) + defer func() { + mockController.Finish() + Log = ctrl.Log + }() + loggerMock := mock_logr.NewMockLogger(mockController) + Log = loggerMock + + loggerMock.EXPECT().WithValues("key", "value").Return(loggerMock) + WithValues("key", "value") +} + +func TestV(t *testing.T) { + mockController := gomock.NewController(t) + defer func() { + mockController.Finish() + Log = ctrl.Log + }() + loggerMock := mock_logr.NewMockLogger(mockController) + Log = loggerMock + + loggerMock.EXPECT().V(1).Return(loggerMock) + V(1) +} diff --git a/pkg/common/log/mocks/mock_logr.go b/pkg/common/log/mocks/mock_logr.go new file mode 100644 index 00000000..f42eff6a --- /dev/null +++ b/pkg/common/log/mocks/mock_logr.go @@ -0,0 +1,260 @@ +// Code generated by MockGen. DO NOT EDIT. +// Source: vendor/github.com/go-logr/logr/logr.go + +// Package mock_logr is a generated GoMock package. +package mock_logr + +import ( + reflect "reflect" + + logr "github.com/go-logr/logr" + gomock "github.com/golang/mock/gomock" +) + +// MockLogger is a mock of Logger interface. +type MockLogger struct { + ctrl *gomock.Controller + recorder *MockLoggerMockRecorder +} + +// MockLoggerMockRecorder is the mock recorder for MockLogger. +type MockLoggerMockRecorder struct { + mock *MockLogger +} + +// NewMockLogger creates a new mock instance. +func NewMockLogger(ctrl *gomock.Controller) *MockLogger { + mock := &MockLogger{ctrl: ctrl} + mock.recorder = &MockLoggerMockRecorder{mock} + return mock +} + +// EXPECT returns an object that allows the caller to indicate expected use. +func (m *MockLogger) EXPECT() *MockLoggerMockRecorder { + return m.recorder +} + +// Enabled mocks base method. +func (m *MockLogger) Enabled() bool { + m.ctrl.T.Helper() + ret := m.ctrl.Call(m, "Enabled") + ret0, _ := ret[0].(bool) + return ret0 +} + +// Enabled indicates an expected call of Enabled. +func (mr *MockLoggerMockRecorder) Enabled() *gomock.Call { + mr.mock.ctrl.T.Helper() + return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "Enabled", reflect.TypeOf((*MockLogger)(nil).Enabled)) +} + +// Error mocks base method. +func (m *MockLogger) Error(err error, msg string, keysAndValues ...interface{}) { + m.ctrl.T.Helper() + varargs := []interface{}{err, msg} + for _, a := range keysAndValues { + varargs = append(varargs, a) + } + m.ctrl.Call(m, "Error", varargs...) +} + +// Error indicates an expected call of Error. +func (mr *MockLoggerMockRecorder) Error(err, msg interface{}, keysAndValues ...interface{}) *gomock.Call { + mr.mock.ctrl.T.Helper() + varargs := append([]interface{}{err, msg}, keysAndValues...) + return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "Error", reflect.TypeOf((*MockLogger)(nil).Error), varargs...) +} + +// Info mocks base method. +func (m *MockLogger) Info(msg string, keysAndValues ...interface{}) { + m.ctrl.T.Helper() + varargs := []interface{}{msg} + for _, a := range keysAndValues { + varargs = append(varargs, a) + } + m.ctrl.Call(m, "Info", varargs...) +} + +// Info indicates an expected call of Info. +func (mr *MockLoggerMockRecorder) Info(msg interface{}, keysAndValues ...interface{}) *gomock.Call { + mr.mock.ctrl.T.Helper() + varargs := append([]interface{}{msg}, keysAndValues...) + return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "Info", reflect.TypeOf((*MockLogger)(nil).Info), varargs...) +} + +// V mocks base method. +func (m *MockLogger) V(level int) logr.Logger { + m.ctrl.T.Helper() + ret := m.ctrl.Call(m, "V", level) + ret0, _ := ret[0].(logr.Logger) + return ret0 +} + +// V indicates an expected call of V. +func (mr *MockLoggerMockRecorder) V(level interface{}) *gomock.Call { + mr.mock.ctrl.T.Helper() + return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "V", reflect.TypeOf((*MockLogger)(nil).V), level) +} + +// WithName mocks base method. +func (m *MockLogger) WithName(name string) logr.Logger { + m.ctrl.T.Helper() + ret := m.ctrl.Call(m, "WithName", name) + ret0, _ := ret[0].(logr.Logger) + return ret0 +} + +// WithName indicates an expected call of WithName. +func (mr *MockLoggerMockRecorder) WithName(name interface{}) *gomock.Call { + mr.mock.ctrl.T.Helper() + return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "WithName", reflect.TypeOf((*MockLogger)(nil).WithName), name) +} + +// WithValues mocks base method. +func (m *MockLogger) WithValues(keysAndValues ...interface{}) logr.Logger { + m.ctrl.T.Helper() + varargs := []interface{}{} + for _, a := range keysAndValues { + varargs = append(varargs, a) + } + ret := m.ctrl.Call(m, "WithValues", varargs...) + ret0, _ := ret[0].(logr.Logger) + return ret0 +} + +// WithValues indicates an expected call of WithValues. +func (mr *MockLoggerMockRecorder) WithValues(keysAndValues ...interface{}) *gomock.Call { + mr.mock.ctrl.T.Helper() + return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "WithValues", reflect.TypeOf((*MockLogger)(nil).WithValues), keysAndValues...) +} + +// MockCallDepthLogger is a mock of CallDepthLogger interface. +type MockCallDepthLogger struct { + ctrl *gomock.Controller + recorder *MockCallDepthLoggerMockRecorder +} + +// MockCallDepthLoggerMockRecorder is the mock recorder for MockCallDepthLogger. +type MockCallDepthLoggerMockRecorder struct { + mock *MockCallDepthLogger +} + +// NewMockCallDepthLogger creates a new mock instance. +func NewMockCallDepthLogger(ctrl *gomock.Controller) *MockCallDepthLogger { + mock := &MockCallDepthLogger{ctrl: ctrl} + mock.recorder = &MockCallDepthLoggerMockRecorder{mock} + return mock +} + +// EXPECT returns an object that allows the caller to indicate expected use. +func (m *MockCallDepthLogger) EXPECT() *MockCallDepthLoggerMockRecorder { + return m.recorder +} + +// Enabled mocks base method. +func (m *MockCallDepthLogger) Enabled() bool { + m.ctrl.T.Helper() + ret := m.ctrl.Call(m, "Enabled") + ret0, _ := ret[0].(bool) + return ret0 +} + +// Enabled indicates an expected call of Enabled. +func (mr *MockCallDepthLoggerMockRecorder) Enabled() *gomock.Call { + mr.mock.ctrl.T.Helper() + return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "Enabled", reflect.TypeOf((*MockCallDepthLogger)(nil).Enabled)) +} + +// Error mocks base method. +func (m *MockCallDepthLogger) Error(err error, msg string, keysAndValues ...interface{}) { + m.ctrl.T.Helper() + varargs := []interface{}{err, msg} + for _, a := range keysAndValues { + varargs = append(varargs, a) + } + m.ctrl.Call(m, "Error", varargs...) +} + +// Error indicates an expected call of Error. +func (mr *MockCallDepthLoggerMockRecorder) Error(err, msg interface{}, keysAndValues ...interface{}) *gomock.Call { + mr.mock.ctrl.T.Helper() + varargs := append([]interface{}{err, msg}, keysAndValues...) + return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "Error", reflect.TypeOf((*MockCallDepthLogger)(nil).Error), varargs...) +} + +// Info mocks base method. +func (m *MockCallDepthLogger) Info(msg string, keysAndValues ...interface{}) { + m.ctrl.T.Helper() + varargs := []interface{}{msg} + for _, a := range keysAndValues { + varargs = append(varargs, a) + } + m.ctrl.Call(m, "Info", varargs...) +} + +// Info indicates an expected call of Info. +func (mr *MockCallDepthLoggerMockRecorder) Info(msg interface{}, keysAndValues ...interface{}) *gomock.Call { + mr.mock.ctrl.T.Helper() + varargs := append([]interface{}{msg}, keysAndValues...) + return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "Info", reflect.TypeOf((*MockCallDepthLogger)(nil).Info), varargs...) +} + +// V mocks base method. +func (m *MockCallDepthLogger) V(level int) logr.Logger { + m.ctrl.T.Helper() + ret := m.ctrl.Call(m, "V", level) + ret0, _ := ret[0].(logr.Logger) + return ret0 +} + +// V indicates an expected call of V. +func (mr *MockCallDepthLoggerMockRecorder) V(level interface{}) *gomock.Call { + mr.mock.ctrl.T.Helper() + return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "V", reflect.TypeOf((*MockCallDepthLogger)(nil).V), level) +} + +// WithCallDepth mocks base method. +func (m *MockCallDepthLogger) WithCallDepth(depth int) logr.Logger { + m.ctrl.T.Helper() + ret := m.ctrl.Call(m, "WithCallDepth", depth) + ret0, _ := ret[0].(logr.Logger) + return ret0 +} + +// WithCallDepth indicates an expected call of WithCallDepth. +func (mr *MockCallDepthLoggerMockRecorder) WithCallDepth(depth interface{}) *gomock.Call { + mr.mock.ctrl.T.Helper() + return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "WithCallDepth", reflect.TypeOf((*MockCallDepthLogger)(nil).WithCallDepth), depth) +} + +// WithName mocks base method. +func (m *MockCallDepthLogger) WithName(name string) logr.Logger { + m.ctrl.T.Helper() + ret := m.ctrl.Call(m, "WithName", name) + ret0, _ := ret[0].(logr.Logger) + return ret0 +} + +// WithName indicates an expected call of WithName. +func (mr *MockCallDepthLoggerMockRecorder) WithName(name interface{}) *gomock.Call { + mr.mock.ctrl.T.Helper() + return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "WithName", reflect.TypeOf((*MockCallDepthLogger)(nil).WithName), name) +} + +// WithValues mocks base method. +func (m *MockCallDepthLogger) WithValues(keysAndValues ...interface{}) logr.Logger { + m.ctrl.T.Helper() + varargs := []interface{}{} + for _, a := range keysAndValues { + varargs = append(varargs, a) + } + ret := m.ctrl.Call(m, "WithValues", varargs...) + ret0, _ := ret[0].(logr.Logger) + return ret0 +} + +// WithValues indicates an expected call of WithValues. +func (mr *MockCallDepthLoggerMockRecorder) WithValues(keysAndValues ...interface{}) *gomock.Call { + mr.mock.ctrl.T.Helper() + return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "WithValues", reflect.TypeOf((*MockCallDepthLogger)(nil).WithValues), keysAndValues...) +} diff --git a/pkg/common/mocks/mock_common.go b/pkg/common/mocks/mock_common.go index 83ae220e..179c8f11 100644 --- a/pkg/common/mocks/mock_common.go +++ b/pkg/common/mocks/mock_common.go @@ -39,6 +39,20 @@ func (m *MockAuthPipeline) EXPECT() *MockAuthPipelineMockRecorder { return m.recorder } +// Evaluate mocks base method. +func (m *MockAuthPipeline) Evaluate() common.AuthResult { + m.ctrl.T.Helper() + ret := m.ctrl.Call(m, "Evaluate") + ret0, _ := ret[0].(common.AuthResult) + return ret0 +} + +// Evaluate indicates an expected call of Evaluate. +func (mr *MockAuthPipelineMockRecorder) Evaluate() *gomock.Call { + mr.mock.ctrl.T.Helper() + return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "Evaluate", reflect.TypeOf((*MockAuthPipeline)(nil).Evaluate)) +} + // GetAPI mocks base method. func (m *MockAuthPipeline) GetAPI() interface{} { m.ctrl.T.Helper() @@ -81,20 +95,6 @@ func (mr *MockAuthPipelineMockRecorder) GetHttp() *gomock.Call { return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "GetHttp", reflect.TypeOf((*MockAuthPipeline)(nil).GetHttp)) } -// GetParentContext mocks base method. -func (m *MockAuthPipeline) GetParentContext() *context.Context { - m.ctrl.T.Helper() - ret := m.ctrl.Call(m, "GetParentContext") - ret0, _ := ret[0].(*context.Context) - return ret0 -} - -// GetParentContext indicates an expected call of GetParentContext. -func (mr *MockAuthPipelineMockRecorder) GetParentContext() *gomock.Call { - mr.mock.ctrl.T.Helper() - return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "GetParentContext", reflect.TypeOf((*MockAuthPipeline)(nil).GetParentContext)) -} - // GetPostAuthorizationData mocks base method. func (m *MockAuthPipeline) GetPostAuthorizationData() interface{} { m.ctrl.T.Helper() diff --git a/pkg/config/authorization.go b/pkg/config/authorization.go index 3d8b1c43..d78947d2 100644 --- a/pkg/config/authorization.go +++ b/pkg/config/authorization.go @@ -5,14 +5,10 @@ import ( "fmt" "github.com/kuadrant/authorino/pkg/common" + "github.com/kuadrant/authorino/pkg/common/log" "github.com/kuadrant/authorino/pkg/config/authorization" ) -var ( - // AuthorizationEvaluator represents the authorizationConfig struct implementing its Call method - AuthorizationEvaluator common.AuthConfigEvaluator -) - type AuthorizationConfig struct { Name string `yaml:"name"` OPA *authorization.OPA `yaml:"opa,omitempty"` @@ -20,7 +16,12 @@ type AuthorizationConfig struct { KubernetesAuthz *authorization.KubernetesAuthz `yaml:"kubernetes,omitempty"` } -func (config *AuthorizationConfig) Call(pipeline common.AuthPipeline, ctx context.Context) (interface{}, error) { +// impl:AuthConfigEvaluator + +func (config *AuthorizationConfig) Call(pipeline common.AuthPipeline, parentCtx context.Context) (interface{}, error) { + logger := log.FromContext(parentCtx).WithName("authorization") + ctx := log.IntoContext(parentCtx, logger) + switch { case config.OPA != nil: return config.OPA.Call(pipeline, ctx) @@ -29,6 +30,6 @@ func (config *AuthorizationConfig) Call(pipeline common.AuthPipeline, ctx contex case config.KubernetesAuthz != nil: return config.KubernetesAuthz.Call(pipeline, ctx) default: - return false, fmt.Errorf("invalid authorization configs") + return false, fmt.Errorf("invalid authorization config") } } diff --git a/pkg/config/authorization/kubernetes_authz.go b/pkg/config/authorization/kubernetes_authz.go index 43a46c57..2b4404a8 100644 --- a/pkg/config/authorization/kubernetes_authz.go +++ b/pkg/config/authorization/kubernetes_authz.go @@ -7,6 +7,7 @@ import ( "strings" "github.com/kuadrant/authorino/pkg/common" + "github.com/kuadrant/authorino/pkg/common/log" kubeAuthz "k8s.io/api/authorization/v1" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" @@ -109,6 +110,8 @@ func (k *KubernetesAuthz) Call(pipeline common.AuthPipeline, ctx context.Context subjectAccessReview.Spec.Groups = k.Groups } + log.FromContext(ctx).WithName("kubernetesauthz").V(1).Info("calling kubernetes subject access review api", "subjectaccessreview", subjectAccessReview) + if result, err := k.authorizer.SubjectAccessReviews().Create(ctx, &subjectAccessReview, metav1.CreateOptions{}); err != nil { return false, err } else { diff --git a/pkg/config/authorization/opa.go b/pkg/config/authorization/opa.go index 3ef1166a..f161240a 100644 --- a/pkg/config/authorization/opa.go +++ b/pkg/config/authorization/opa.go @@ -11,9 +11,9 @@ import ( "github.com/kuadrant/authorino/pkg/common" "github.com/kuadrant/authorino/pkg/common/auth_credentials" + "github.com/kuadrant/authorino/pkg/common/log" "github.com/open-policy-agent/opa/rego" - ctrl "sigs.k8s.io/controller-runtime" ) const ( @@ -28,15 +28,13 @@ default allow = false invalidOPAResponseErrorMsg = "Invalid response from OPA policy evaluation" ) -var ( - opaLog = ctrl.Log.WithName("Authorino").WithName("OPA") -) +func NewOPAAuthorization(policyName string, rego string, externalSource OPAExternalSource, nonce int, ctx context.Context) (*OPA, error) { + logger := log.FromContext(ctx).WithName("opa") -func NewOPAAuthorization(policyName string, rego string, externalSource OPAExternalSource, nonce int) (*OPA, error) { if rego == "" && externalSource.Endpoint != "" { downloadedRego, err := externalSource.downloadRegoDataFromUrl() if err != nil { - opaLog.Error(err, regoDownloadErrorMsg, "secret", policyName) + logger.Error(err, regoDownloadErrorMsg, "secret", policyName) return nil, err } rego = downloadedRego @@ -51,7 +49,7 @@ func NewOPAAuthorization(policyName string, rego string, externalSource OPAExter opaContext: context.TODO(), } if err := o.precompilePolicy(); err != nil { - opaLog.Error(err, opaPolicyPrecompileErrorMsg, "secret", policyName) + logger.Error(err, opaPolicyPrecompileErrorMsg, "secret", policyName) return nil, err } else { return o, nil diff --git a/pkg/config/authorization/opa_test.go b/pkg/config/authorization/opa_test.go index 64dacc72..e4b27f89 100644 --- a/pkg/config/authorization/opa_test.go +++ b/pkg/config/authorization/opa_test.go @@ -1,6 +1,7 @@ package authorization import ( + "context" "fmt" "strings" "testing" @@ -36,7 +37,7 @@ type authorizationData struct { } func TestNewOPAAuthorizationInlineRego(t *testing.T) { - opa, err := NewOPAAuthorization("test-opa", regoData, OPAExternalSource{}, 0) + opa, err := NewOPAAuthorization("test-opa", regoData, OPAExternalSource{}, 0, context.TODO()) assert.NilError(t, err) assertOPAAuthorization(t, opa) @@ -54,7 +55,7 @@ func TestNewOPAAuthorizationExternalUrl(t *testing.T) { AuthCredentials: auth_credentials.NewAuthCredential("", ""), } - opa, err := NewOPAAuthorization("test-opa", "", externalSource, 0) + opa, err := NewOPAAuthorization("test-opa", "", externalSource, 0, context.TODO()) assert.NilError(t, err) assertOPAAuthorization(t, opa) @@ -72,7 +73,7 @@ func TestNewOPAAuthorizationBoth(t *testing.T) { AuthCredentials: auth_credentials.NewAuthCredential("", ""), } - opa, err := NewOPAAuthorization("test-opa", regoData, externalSource, 0) + opa, err := NewOPAAuthorization("test-opa", regoData, externalSource, 0, context.TODO()) assert.NilError(t, err) assertOPAAuthorization(t, opa) @@ -80,7 +81,7 @@ func TestNewOPAAuthorizationBoth(t *testing.T) { func TestNewOPAAuthorizationWithPackageInRego(t *testing.T) { data := fmt.Sprintf("package my-rego-123\n%s", regoData) - opa, err := NewOPAAuthorization("test-opa", data, OPAExternalSource{}, 0) + opa, err := NewOPAAuthorization("test-opa", data, OPAExternalSource{}, 0, context.TODO()) assert.NilError(t, err) assert.Assert(t, !strings.Contains(opa.Rego, "package")) @@ -99,7 +100,7 @@ func TestNewOPAAuthorizationJsonResponse(t *testing.T) { AuthCredentials: auth_credentials.NewAuthCredential("", ""), } - opa, err := NewOPAAuthorization("test-opa", "", externalSource, 0) + opa, err := NewOPAAuthorization("test-opa", "", externalSource, 0, context.TODO()) assert.NilError(t, err) assert.Assert(t, !strings.Contains(opa.Rego, "package")) diff --git a/pkg/config/identity.go b/pkg/config/identity.go index a7226f49..0fb4c734 100644 --- a/pkg/config/identity.go +++ b/pkg/config/identity.go @@ -7,17 +7,13 @@ import ( "github.com/kuadrant/authorino/pkg/common" "github.com/kuadrant/authorino/pkg/common/auth_credentials" + "github.com/kuadrant/authorino/pkg/common/log" "github.com/kuadrant/authorino/pkg/config/identity" v1 "k8s.io/api/core/v1" "k8s.io/apimachinery/pkg/types" ) -var ( - // IdentityEvaluator represents the identityConfig struct implementing its Call method - IdentityEvaluator common.AuthConfigEvaluator -) - type IdentityConfig struct { Name string `yaml:"name"` ExtendedProperties []common.JSONProperty `yaml:"extendedProperties"` @@ -30,10 +26,6 @@ type IdentityConfig struct { KubernetesAuth *identity.KubernetesAuth `yaml:"kubernetes,omitempty"` } -func init() { - IdentityEvaluator = &IdentityConfig{} -} - func (config *IdentityConfig) GetAuthConfigEvaluator() common.AuthConfigEvaluator { switch { case config.OAuth2 != nil: @@ -57,7 +49,8 @@ func (config *IdentityConfig) GetAuthConfigEvaluator() common.AuthConfigEvaluato func (config *IdentityConfig) Call(pipeline common.AuthPipeline, ctx context.Context) (interface{}, error) { if evaluator := config.GetAuthConfigEvaluator(); evaluator != nil { - return evaluator.Call(pipeline, ctx) + logger := log.FromContext(ctx).WithName("identity") + return evaluator.Call(pipeline, log.IntoContext(ctx, logger)) } else { return nil, fmt.Errorf("invalid identity config") } diff --git a/pkg/config/identity/api_key.go b/pkg/config/identity/api_key.go index fecdcc09..b47f0c66 100644 --- a/pkg/config/identity/api_key.go +++ b/pkg/config/identity/api_key.go @@ -6,18 +6,16 @@ import ( "github.com/kuadrant/authorino/pkg/common" "github.com/kuadrant/authorino/pkg/common/auth_credentials" + "github.com/kuadrant/authorino/pkg/common/log" v1 "k8s.io/api/core/v1" "k8s.io/apimachinery/pkg/types" - ctrl "sigs.k8s.io/controller-runtime" "sigs.k8s.io/controller-runtime/pkg/client" ) const ( apiKeySelector = "api_key" invalidApiKeyMsg = "the API Key provided is invalid" - noApiKeysFoundMsg = "no API Keys were found on the request" - authSuccessfulMsg = "Successfully authenticated with the provided API key" credentialsFetchingErrorMsg = "Something went wrong fetching the authorized credentials" ) @@ -34,12 +32,8 @@ type APIKey struct { apiKeyDetails } -var ( - apiKeyLog = ctrl.Log.WithName("Authorino").WithName("ApiKey") -) - // NewApiKeyIdentity creates a new instance of APIKey -func NewApiKeyIdentity(name string, labelSelectors map[string]string, authCred auth_credentials.AuthCredentials, k8sClient client.Reader) *APIKey { +func NewApiKeyIdentity(name string, labelSelectors map[string]string, authCred auth_credentials.AuthCredentials, k8sClient client.Reader, ctx context.Context) *APIKey { apiKey := &APIKey{ authCred, apiKeyDetails{ @@ -50,7 +44,7 @@ func NewApiKeyIdentity(name string, labelSelectors map[string]string, authCred a }, } if err := apiKey.GetCredentialsFromCluster(context.TODO()); err != nil { - apiKeyLog.Error(err, credentialsFetchingErrorMsg) + log.FromContext(ctx).WithName("apikey").Error(err, credentialsFetchingErrorMsg) } return apiKey } @@ -74,18 +68,15 @@ func (apiKey *APIKey) GetCredentialsFromCluster(ctx context.Context) error { // Call will evaluate the credentials within the request against the authorized ones func (apiKey *APIKey) Call(pipeline common.AuthPipeline, _ context.Context) (interface{}, error) { if reqKey, err := apiKey.GetCredentialsFromReq(pipeline.GetHttp()); err != nil { - apiKeyLog.Error(err, noApiKeysFoundMsg) return nil, err } else { for key, secret := range apiKey.authorizedCredentials { if key == reqKey { - apiKeyLog.Info(authSuccessfulMsg, "secret", secret) return secret, nil } } } err := fmt.Errorf(invalidApiKeyMsg) - apiKeyLog.Error(err, invalidApiKeyMsg) return nil, err } diff --git a/pkg/config/identity/api_key_test.go b/pkg/config/identity/api_key_test.go index 7d9c57d3..e1f2fdd2 100644 --- a/pkg/config/identity/api_key_test.go +++ b/pkg/config/identity/api_key_test.go @@ -46,15 +46,13 @@ func mockAuthPipeline(ctrl *Controller) (pipelineMock *MockAuthPipeline) { func TestConstants(t *testing.T) { assert.Check(t, "api_key" == apiKeySelector) assert.Check(t, "the API Key provided is invalid" == invalidApiKeyMsg) - assert.Check(t, "no API Keys were found on the request" == noApiKeysFoundMsg) - assert.Check(t, "Successfully authenticated with the provided API key" == authSuccessfulMsg) } func TestNewApiKeyIdentity(t *testing.T) { ctrl := NewController(t) defer ctrl.Finish() - apiKey := NewApiKeyIdentity("jedi", map[string]string{"planet": "tatooine"}, NewMockAuthCredentials(ctrl), &MockK8sClient{}) + apiKey := NewApiKeyIdentity("jedi", map[string]string{"planet": "tatooine"}, NewMockAuthCredentials(ctrl), &MockK8sClient{}, context.TODO()) assert.Check(t, apiKey.Name == "jedi") assert.Check(t, apiKey.LabelSelectors["planet"] == "tatooine") @@ -73,7 +71,7 @@ func TestCallSuccess(t *testing.T) { authCredMock := NewMockAuthCredentials(ctrl) authCredMock.EXPECT().GetCredentialsFromReq(Any()).Return("ObiWanKenobiLightSaber", nil) - apiKey := NewApiKeyIdentity("jedi", map[string]string{"planet": "tatooine"}, authCredMock, &MockK8sClient{}) + apiKey := NewApiKeyIdentity("jedi", map[string]string{"planet": "tatooine"}, authCredMock, &MockK8sClient{}, context.TODO()) auth, err := apiKey.Call(pipelineMock, context.TODO()) assert.NilError(t, err) @@ -88,7 +86,7 @@ func TestCallNoApiKeyFail(t *testing.T) { authCredMock := NewMockAuthCredentials(ctrl) authCredMock.EXPECT().GetCredentialsFromReq(Any()).Return("", fmt.Errorf("something went wrong getting the API Key")) - apiKey := NewApiKeyIdentity("jedi", map[string]string{"planet": "tatooine"}, authCredMock, &MockK8sClient{}) + apiKey := NewApiKeyIdentity("jedi", map[string]string{"planet": "tatooine"}, authCredMock, &MockK8sClient{}, context.TODO()) _, err := apiKey.Call(pipelineMock, context.TODO()) @@ -104,16 +102,16 @@ func TestCallInvalidApiKeyFail(t *testing.T) { authCredMock := NewMockAuthCredentials(ctrl) authCredMock.EXPECT().GetCredentialsFromReq(Any()).Return("ASithLightSaber", nil) - apiKey := NewApiKeyIdentity("jedi", map[string]string{"planet": "tatooine"}, authCredMock, &MockK8sClient{}) + apiKey := NewApiKeyIdentity("jedi", map[string]string{"planet": "tatooine"}, authCredMock, &MockK8sClient{}, context.TODO()) _, err := apiKey.Call(pipelineMock, context.TODO()) assert.Error(t, err, "the API Key provided is invalid") } func TestGetCredentialsFromClusterSuccess(t *testing.T) { - apiKey := NewApiKeyIdentity("X-API-KEY", map[string]string{"planet": "tatooine"}, nil, &MockK8sClient{}) - err := apiKey.GetCredentialsFromCluster(context.TODO()) + apiKey := NewApiKeyIdentity("X-API-KEY", map[string]string{"planet": "tatooine"}, nil, &MockK8sClient{}, nil) + err := apiKey.GetCredentialsFromCluster(context.TODO()) assert.NilError(t, err) assert.Check(t, len(apiKey.authorizedCredentials) == 2) @@ -130,8 +128,8 @@ func TestGetCredentialsFromClusterFail(t *testing.T) { listSecretsFunc = func(list *v1.SecretList) error { return fmt.Errorf("something terribly wrong happened") } - apiKey := NewApiKeyIdentity("X-API-KEY", map[string]string{"planet": "tatooine"}, nil, &MockK8sClient{}) - err := apiKey.GetCredentialsFromCluster(context.TODO()) + apiKey := NewApiKeyIdentity("X-API-KEY", map[string]string{"planet": "tatooine"}, nil, &MockK8sClient{}, context.TODO()) + err := apiKey.GetCredentialsFromCluster(context.TODO()) assert.Error(t, err, "something terribly wrong happened") } diff --git a/pkg/config/identity/kubernetes_auth.go b/pkg/config/identity/kubernetes_auth.go index d8270dc7..a0904a06 100644 --- a/pkg/config/identity/kubernetes_auth.go +++ b/pkg/config/identity/kubernetes_auth.go @@ -6,6 +6,7 @@ import ( "github.com/kuadrant/authorino/pkg/common" "github.com/kuadrant/authorino/pkg/common/auth_credentials" + "github.com/kuadrant/authorino/pkg/common/log" jwt "github.com/dgrijalva/jwt-go" authv1 "k8s.io/api/authentication/v1" @@ -67,6 +68,8 @@ func (kubeAuth *KubernetesAuth) Call(pipeline common.AuthPipeline, ctx context.C }, } + log.FromContext(ctx).WithName("kubernetesauth").V(1).Info("calling kubernetes token review api", "tokenreview", tr) + if result, err := kubeAuth.authenticator.TokenReviews().Create(ctx, &tr, metav1.CreateOptions{}); err != nil { return nil, err } else { diff --git a/pkg/config/identity/oauth2.go b/pkg/config/identity/oauth2.go index 7202fcf0..b3002244 100644 --- a/pkg/config/identity/oauth2.go +++ b/pkg/config/identity/oauth2.go @@ -9,6 +9,7 @@ import ( "github.com/kuadrant/authorino/pkg/common" "github.com/kuadrant/authorino/pkg/common/auth_credentials" + "github.com/kuadrant/authorino/pkg/common/log" ) type OAuth2 struct { @@ -56,13 +57,16 @@ func (oauth *OAuth2) Call(pipeline common.AuthPipeline, ctx context.Context) (in "token": {accessToken}, "token_type_hint": {oauth.TokenTypeHint}, } + encodedFormData := formData.Encode() - req, err := http.NewRequestWithContext(ctx, "POST", tokenIntrospectionURL.String(), bytes.NewBufferString(formData.Encode())) + req, err := http.NewRequestWithContext(ctx, "POST", tokenIntrospectionURL.String(), bytes.NewBufferString(encodedFormData)) req.Header.Set("Content-Type", "application/x-www-form-urlencoded") if err != nil { return nil, err } + log.FromContext(ctx).WithName("oauth2").V(1).Info("sending token introspection request", "url", tokenIntrospectionURL.String(), "data", encodedFormData) + resp, err := http.DefaultClient.Do(req) if err != nil { return nil, err diff --git a/pkg/config/identity/oidc.go b/pkg/config/identity/oidc.go index ccbd0e5b..23c96c46 100644 --- a/pkg/config/identity/oidc.go +++ b/pkg/config/identity/oidc.go @@ -6,25 +6,23 @@ import ( "github.com/kuadrant/authorino/pkg/common" "github.com/kuadrant/authorino/pkg/common/auth_credentials" + "github.com/kuadrant/authorino/pkg/common/log" goidc "github.com/coreos/go-oidc" - ctrl "sigs.k8s.io/controller-runtime" ) -var oidcLogger = ctrl.Log.WithName("authorino").WithName("identity").WithName("oidc") - type OIDC struct { auth_credentials.AuthCredentials Endpoint string `yaml:"endpoint"` provider *goidc.Provider } -func NewOIDC(endpoint string, creds auth_credentials.AuthCredentials) *OIDC { +func NewOIDC(endpoint string, creds auth_credentials.AuthCredentials, ctx context.Context) *OIDC { oidc := &OIDC{ AuthCredentials: creds, Endpoint: endpoint, } - _ = oidc.getProvider() + _ = oidc.getProvider(log.IntoContext(ctx, log.FromContext(ctx).WithName("oidc"))) return oidc } @@ -38,18 +36,18 @@ func (oidc *OIDC) Call(pipeline common.AuthPipeline, ctx context.Context) (inter // verify jwt and extract claims var claims interface{} - if _, err := oidc.decodeAndVerifyToken(accessToken, ctx, &claims); err != nil { + if _, err := oidc.decodeAndVerifyToken(accessToken, log.IntoContext(ctx, log.FromContext(ctx).WithName("oidc")), &claims); err != nil { return nil, err } else { return claims, nil } } -func (oidc *OIDC) getProvider() *goidc.Provider { +func (oidc *OIDC) getProvider(ctx context.Context) *goidc.Provider { if oidc.provider == nil { endpoint := oidc.Endpoint if provider, err := goidc.NewProvider(context.TODO(), endpoint); err != nil { - oidcLogger.Error(err, "failed to discovery openid connect configuration", "endpoint", endpoint) + log.FromContext(ctx).Error(err, "failed to discovery openid connect configuration", "endpoint", endpoint) } else { oidc.provider = provider } @@ -80,16 +78,16 @@ func (oidc *OIDC) decodeAndVerifyToken(accessToken string, ctx context.Context, func (oidc *OIDC) verifyToken(accessToken string, ctx context.Context) (*goidc.IDToken, error) { tokenVerifierConfig := &goidc.Config{SkipClientIDCheck: true, SkipIssuerCheck: true} - if idToken, err := oidc.getProvider().Verifier(tokenVerifierConfig).Verify(ctx, accessToken); err != nil { + if idToken, err := oidc.getProvider(ctx).Verifier(tokenVerifierConfig).Verify(ctx, accessToken); err != nil { return nil, err } else { return idToken, nil } } -func (oidc *OIDC) GetURL(name string) (*url.URL, error) { +func (oidc *OIDC) GetURL(name string, ctx context.Context) (*url.URL, error) { var providerClaims map[string]interface{} - _ = oidc.getProvider().Claims(&providerClaims) + _ = oidc.getProvider(ctx).Claims(&providerClaims) if endpoint, err := url.Parse(providerClaims[name].(string)); err != nil { return nil, err diff --git a/pkg/config/metadata.go b/pkg/config/metadata.go index ed78b75e..ca54a8ce 100644 --- a/pkg/config/metadata.go +++ b/pkg/config/metadata.go @@ -5,6 +5,7 @@ import ( "fmt" "github.com/kuadrant/authorino/pkg/common" + "github.com/kuadrant/authorino/pkg/common/log" "github.com/kuadrant/authorino/pkg/config/metadata" ) @@ -14,11 +15,6 @@ const ( metadataGenericHTTP = "METADATA_GENERIC_HTTP" ) -var ( - // MetadataEvaluator represents the metadataStruct implementing its Call method - MetadataEvaluator common.AuthConfigEvaluator -) - type MetadataConfig struct { Name string `yaml:"name"` UserInfo *metadata.UserInfo `yaml:"userinfo,omitempty"` @@ -26,37 +22,46 @@ type MetadataConfig struct { GenericHTTP *metadata.GenericHttp `yaml:"http,omitempty"` } -func init() { - MetadataEvaluator = &MetadataConfig{} +func (config *MetadataConfig) GetType() (string, error) { + switch { + case config.UserInfo != nil: + return metadataUserInfo, nil + case config.UMA != nil: + return metadataUMA, nil + case config.GenericHTTP != nil: + return metadataGenericHTTP, nil + default: + return "", fmt.Errorf("invalid metadata config") + } } -func (config *MetadataConfig) Call(pipeline common.AuthPipeline, ctx context.Context) (interface{}, error) { +func (config *MetadataConfig) GetAuthConfigEvaluator() common.AuthConfigEvaluator { t, _ := config.GetType() switch t { case metadataUserInfo: - return config.UserInfo.Call(pipeline, ctx) + return config.UserInfo case metadataUMA: - return config.UMA.Call(pipeline, ctx) + return config.UMA case metadataGenericHTTP: - return config.GenericHTTP.Call(pipeline, ctx) + return config.GenericHTTP default: - return "", fmt.Errorf("invalid metadata config") + return nil } } -func (config *MetadataConfig) GetType() (string, error) { - switch { - case config.UserInfo != nil: - return metadataUserInfo, nil - case config.UMA != nil: - return metadataUMA, nil - case config.GenericHTTP != nil: - return metadataGenericHTTP, nil - default: - return "", fmt.Errorf("invalid metadata config") +// impl:AuthConfigEvaluator + +func (config *MetadataConfig) Call(pipeline common.AuthPipeline, ctx context.Context) (interface{}, error) { + if evaluator := config.GetAuthConfigEvaluator(); evaluator != nil { + logger := log.FromContext(ctx).WithName("metadata") + return evaluator.Call(pipeline, log.IntoContext(ctx, logger)) + } else { + return nil, fmt.Errorf("invalid metadata config") } } +// impl:NamedConfigEvaluator + func (config *MetadataConfig) GetName() string { return config.Name } diff --git a/pkg/config/metadata/generic_http.go b/pkg/config/metadata/generic_http.go index 8f006ef1..40387ba9 100644 --- a/pkg/config/metadata/generic_http.go +++ b/pkg/config/metadata/generic_http.go @@ -11,6 +11,7 @@ import ( "github.com/kuadrant/authorino/pkg/common" "github.com/kuadrant/authorino/pkg/common/auth_credentials" + "github.com/kuadrant/authorino/pkg/common/log" ) type GenericHttp struct { @@ -56,6 +57,20 @@ func (h *GenericHttp) Call(pipeline common.AuthPipeline, ctx context.Context) (i req.Header.Set("Content-Type", contentType) + if logger := log.FromContext(ctx).WithName("http").V(1); logger.Enabled() { + logData := []interface{}{ + "method", method, + "url", endpoint, + "headers", req.Header, + } + if requestBody != nil { + var b []byte + _, _ = requestBody.Read(b) + logData = append(logData, "body", string(b)) + } + logger.Info("sending request", logData...) + } + resp, err := http.DefaultClient.Do(req) if err != nil { return nil, err diff --git a/pkg/config/metadata/uma.go b/pkg/config/metadata/uma.go index 47dc6ad3..20aef523 100644 --- a/pkg/config/metadata/uma.go +++ b/pkg/config/metadata/uma.go @@ -10,6 +10,7 @@ import ( "sync" "github.com/kuadrant/authorino/pkg/common" + "github.com/kuadrant/authorino/pkg/common/log" ) type providerJSON struct { @@ -51,6 +52,8 @@ func (provider *Provider) queryResourcesByURI(uri string, pat PAT, ctx context.C queryResourcesURL, _ := url.Parse(provider.resourceRegistrationURL) queryResourcesURL.RawQuery = "uri=" + uri + log.FromContext(ctx).V(1).Info("querying resources by uri", "url", queryResourcesURL.String()) + var resourceIDs []string if err := pat.Get(queryResourcesURL.String(), ctx, &resourceIDs); err != nil { return nil, err @@ -96,6 +99,9 @@ func (provider *Provider) getResourceByID(resourceID string, pat PAT, ctx contex resourceURL, _ := url.Parse(provider.resourceRegistrationURL) resourceURL.Path += "/" + resourceID + + log.FromContext(ctx).V(1).Info("getting resource data", "url", resourceURL.String()) + var data interface{} if err := pat.Get(resourceURL.String(), ctx, &data); err != nil { return nil, err @@ -187,7 +193,9 @@ func (uma *UMA) discover() error { } } -func (uma *UMA) Call(pipeline common.AuthPipeline, ctx context.Context) (interface{}, error) { +func (uma *UMA) Call(pipeline common.AuthPipeline, parentCtx context.Context) (interface{}, error) { + ctx := log.IntoContext(parentCtx, log.FromContext(parentCtx).WithName("uma")) + // get the protection API token (PAT) var pat PAT if err := uma.requestPAT(ctx, &pat); err != nil { @@ -229,6 +237,8 @@ func (uma *UMA) requestPAT(ctx context.Context, pat *PAT) error { } req.Header.Set("Content-Type", "application/x-www-form-urlencoded") + log.FromContext(ctx).V(1).Info("requesting pat", "url", tokenURL.String(), "data", encodedData, "headers", req.Header) + // get the response resp, err := http.DefaultClient.Do(req) if err != nil { diff --git a/pkg/config/metadata/user_info.go b/pkg/config/metadata/user_info.go index 823522cd..fc26129a 100644 --- a/pkg/config/metadata/user_info.go +++ b/pkg/config/metadata/user_info.go @@ -7,6 +7,7 @@ import ( "net/http" "github.com/kuadrant/authorino/pkg/common" + "github.com/kuadrant/authorino/pkg/common/log" "github.com/kuadrant/authorino/pkg/config/identity" ) @@ -14,7 +15,8 @@ type UserInfo struct { OIDC *identity.OIDC `yaml:"oidc,omitempty"` } -func (userinfo *UserInfo) Call(pipeline common.AuthPipeline, ctx context.Context) (interface{}, error) { +func (userinfo *UserInfo) Call(pipeline common.AuthPipeline, parentCtx context.Context) (interface{}, error) { + ctx := log.IntoContext(parentCtx, log.FromContext(parentCtx).WithName("userinfo")) oidc := userinfo.OIDC // check if corresponding oidc identity was resolved @@ -31,7 +33,7 @@ func (userinfo *UserInfo) Call(pipeline common.AuthPipeline, ctx context.Context } // fetch user info - if userInfoURL, err := oidc.GetURL("userinfo_endpoint"); err != nil { + if userInfoURL, err := oidc.GetURL("userinfo_endpoint", ctx); err != nil { return nil, err } else { return fetchUserInfo(userInfoURL.String(), accessToken, ctx) @@ -43,6 +45,8 @@ func fetchUserInfo(userInfoEndpoint string, accessToken string, ctx context.Cont return nil, err } + log.FromContext(ctx).V(1).Info("fetching user info", "endpoint", userInfoEndpoint) + req, err := http.NewRequestWithContext(ctx, "GET", userInfoEndpoint, nil) req.Header.Set("Authorization", "Bearer "+accessToken) if err != nil { diff --git a/pkg/config/metadata/user_info_test.go b/pkg/config/metadata/user_info_test.go index bfbd52df..5e7cad73 100644 --- a/pkg/config/metadata/user_info_test.go +++ b/pkg/config/metadata/user_info_test.go @@ -38,7 +38,7 @@ type userInfoTestData struct { func newUserInfoTestData(ctrl *Controller) userInfoTestData { authCredMock := NewMockAuthCredentials(ctrl) - newOIDC := identity.NewOIDC(fmt.Sprintf("http://%s", authServerHost), authCredMock) + newOIDC := identity.NewOIDC(fmt.Sprintf("http://%s", authServerHost), authCredMock, context.TODO()) ctx, cancel := context.WithCancel(context.TODO()) return userInfoTestData{ ctx, @@ -98,7 +98,7 @@ func TestUserInfoMissingOIDCConfig(t *testing.T) { defer ctrl.Finish() ta := newUserInfoTestData(ctrl) - otherOidcEvaluator := identity.NewOIDC("http://wrongServer", ta.authCredMock) + otherOidcEvaluator := identity.NewOIDC("http://wrongServer", ta.authCredMock, context.TODO()) ta.idConfEvalMock.EXPECT().GetOIDC().Return(otherOidcEvaluator) ta.pipelineMock.EXPECT().GetResolvedIdentity().Return(ta.idConfEvalMock, nil) diff --git a/pkg/config/response.go b/pkg/config/response.go index 2ae93d02..1da541eb 100644 --- a/pkg/config/response.go +++ b/pkg/config/response.go @@ -5,6 +5,7 @@ import ( "fmt" "github.com/kuadrant/authorino/pkg/common" + "github.com/kuadrant/authorino/pkg/common/log" "github.com/kuadrant/authorino/pkg/config/response" ) @@ -45,6 +46,17 @@ type ResponseConfig struct { DynamicJSON *response.DynamicJSON `yaml:"json,omitempty"` } +func (config *ResponseConfig) GetType() (string, error) { + switch { + case config.Wristband != nil: + return RESPONSE_WRISTBAND, nil + case config.DynamicJSON != nil: + return RESPONSE_DYNAMIC_JSON, nil + default: + return "", fmt.Errorf("invalid response config") + } +} + func (config *ResponseConfig) GetAuthConfigEvaluator() common.AuthConfigEvaluator { t, _ := config.GetType() switch t { @@ -57,22 +69,12 @@ func (config *ResponseConfig) GetAuthConfigEvaluator() common.AuthConfigEvaluato } } -func (config *ResponseConfig) GetType() (string, error) { - switch { - case config.Wristband != nil: - return RESPONSE_WRISTBAND, nil - case config.DynamicJSON != nil: - return RESPONSE_DYNAMIC_JSON, nil - default: - return "", fmt.Errorf("invalid response config") - } -} - // impl:AuthConfigEvaluator func (config *ResponseConfig) Call(pipeline common.AuthPipeline, ctx context.Context) (interface{}, error) { if evaluator := config.GetAuthConfigEvaluator(); evaluator != nil { - return evaluator.Call(pipeline, ctx) + logger := log.FromContext(ctx).WithName("response") + return evaluator.Call(pipeline, log.IntoContext(ctx, logger)) } else { return nil, fmt.Errorf("invalid response config") } diff --git a/pkg/service/auth.go b/pkg/service/auth.go index 53ea1e0b..a9cb9358 100644 --- a/pkg/service/auth.go +++ b/pkg/service/auth.go @@ -1,13 +1,13 @@ package service import ( - "encoding/json" "strings" "golang.org/x/net/context" - ctrl "sigs.k8s.io/controller-runtime" "github.com/kuadrant/authorino/pkg/cache" + "github.com/kuadrant/authorino/pkg/common" + "github.com/kuadrant/authorino/pkg/common/log" "github.com/kuadrant/authorino/pkg/config" envoy_core "github.com/envoyproxy/go-control-plane/envoy/config/core/v3" @@ -26,8 +26,6 @@ const ( ) var ( - authServiceLog = ctrl.Log.WithName("Authorino").WithName("AuthService") - statusCodeMapping = map[rpc.Code]envoy_type.StatusCode{ rpc.FAILED_PRECONDITION: envoy_type.StatusCode_BadRequest, rpc.NOT_FOUND: envoy_type.StatusCode_NotFound, @@ -36,28 +34,6 @@ var ( } ) -// AuthResult holds the result data for building the response to an auth check -type AuthResult struct { - // Code is gRPC response code to the auth check - Code rpc.Code - // Status is HTTP status code to override the default mapping between gRPC response codes and HTTP status messages - // for auth - Status envoy_type.StatusCode - // Message is X-Ext-Auth-Reason message returned in an injected HTTP response header, to explain the reason of the - // auth check result - Message string - // Headers are other HTTP headers to inject in the response - Headers []map[string]string - // Metadata are Envoy dynamic metadata content - Metadata map[string]interface{} -} - -// Success tells whether the auth check result was successful and therefore access can be granted to the requested -// resource or it has failed (deny access) -func (result *AuthResult) Success() bool { - return result.Code == rpc.OK -} - // AuthService is the server API for the authorization service. type AuthService struct { Cache cache.Cache @@ -65,43 +41,46 @@ type AuthService struct { // Check performs authorization check based on the attributes associated with the incoming request, // and returns status `OK` or not `OK`. -func (self *AuthService) Check(ctx context.Context, req *envoy_auth.CheckRequest) (*envoy_auth.CheckResponse, error) { - reqJSON, err := json.MarshalIndent(req, "", " ") - if err != nil { - return self.deniedResponse(AuthResult{Code: rpc.FAILED_PRECONDITION, Message: RESPONSE_MESSAGE_INVALID_REQUEST}), nil - } - authServiceLog.Info("Check()", "reqJSON", string(reqJSON)) +func (a *AuthService) Check(parentContext context.Context, req *envoy_auth.CheckRequest) (*envoy_auth.CheckResponse, error) { + requestLogger := log.WithName("service").WithName("auth").WithValues("request id", req.Attributes.Request.Http.GetId()) + ctx := log.IntoContext(parentContext, requestLogger) + + a.logAuthRequest(req, ctx) + + requestData := req.Attributes.Request.Http // service config - host := req.Attributes.Request.Http.Host + host := requestData.Host var apiConfig *config.APIConfig - apiConfig = self.Cache.Get(host) + apiConfig = a.Cache.Get(host) // If the host is not found, but contains a port, remove the port part and retry. if apiConfig == nil && strings.Contains(host, ":") { splitHost := strings.Split(host, ":") - apiConfig = self.Cache.Get(splitHost[0]) + apiConfig = a.Cache.Get(splitHost[0]) } // If we couldn't find the APIConfig in the config, we return and deny. if apiConfig == nil { - return self.deniedResponse(AuthResult{Code: rpc.NOT_FOUND, Message: RESPONSE_MESSAGE_SERVICE_NOT_FOUND}), nil + result := common.AuthResult{Code: rpc.NOT_FOUND, Message: RESPONSE_MESSAGE_SERVICE_NOT_FOUND} + a.logAuthResult(result, ctx) + return a.deniedResponse(result), nil } - pipeline := NewAuthPipeline(ctx, req, *apiConfig) + pipeline := NewAuthPipeline(log.IntoContext(ctx, requestLogger), req, *apiConfig) result := pipeline.Evaluate() - authServiceLog.Info("Check()", "result", result) + a.logAuthResult(result, ctx) if result.Success() { - return self.successResponse(result), nil + return a.successResponse(result, ctx), nil } else { - return self.deniedResponse(result), nil + return a.deniedResponse(result), nil } } -func (self *AuthService) successResponse(authResult AuthResult) *envoy_auth.CheckResponse { +func (a *AuthService) successResponse(authResult common.AuthResult, ctx context.Context) *envoy_auth.CheckResponse { dynamicMetadata, err := structpb.NewStruct(authResult.Metadata) if err != nil { - authServiceLog.Error(err, "failed to create dynamic metadata", "obj", authResult.Metadata) + log.FromContext(ctx).V(1).Error(err, "failed to create dynamic metadata", "object", authResult.Metadata) } return &envoy_auth.CheckResponse{ Status: &rpcstatus.Status{ @@ -116,7 +95,7 @@ func (self *AuthService) successResponse(authResult AuthResult) *envoy_auth.Chec } } -func (self *AuthService) deniedResponse(authResult AuthResult) *envoy_auth.CheckResponse { +func (a *AuthService) deniedResponse(authResult common.AuthResult) *envoy_auth.CheckResponse { code := authResult.Code httpCode := authResult.Status @@ -139,6 +118,67 @@ func (self *AuthService) deniedResponse(authResult AuthResult) *envoy_auth.Check } } +func (a *AuthService) logAuthRequest(req *envoy_auth.CheckRequest, ctx context.Context) { + logger := log.FromContext(ctx) + reqAttrs := req.Attributes + httpAttrs := reqAttrs.Request.Http + + reducedReq := &struct { + Source *envoy_auth.AttributeContext_Peer `json:"source,omitempty"` + Destination *envoy_auth.AttributeContext_Peer `json:"destination,omitempty"` + Request interface{} `json:"request,omitempty"` + }{ + Source: reqAttrs.Source, + Destination: reqAttrs.Destination, + Request: struct { + Http interface{} `json:"http,omitempty"` + }{ + Http: struct { + Id string `json:"id,omitempty"` + Method string `json:"method,omitempty"` + Path string `json:"path,omitempty"` + Host string `json:"host,omitempty"` + Scheme string `json:"scheme,omitempty"` + }{ + Id: httpAttrs.Id, + Method: httpAttrs.Method, + Path: strings.Split(httpAttrs.Path, "?")[0], + Host: httpAttrs.Host, + Scheme: httpAttrs.Scheme, + }, + }, + } + logger.Info("incoming authorization request", "object", reducedReq) // info + + if logger.V(1).Enabled() { + logger.V(1).Info("incoming authorization request", "object", &reqAttrs) // debug + } +} + +func (a *AuthService) logAuthResult(result common.AuthResult, ctx context.Context) { + logger := log.FromContext(ctx) + success := result.Success() + baseLogData := []interface{}{"authorized", success, "response", result.Code.String()} + + logData := baseLogData + if !success { + reducedResult := common.AuthResult{ + Code: result.Code, + Status: result.Status, + Message: result.Message, + } + logData = append(logData, "object", reducedResult) + } + logger.Info("outgoing authorization response", logData...) // info + + if logger.V(1).Enabled() { + if !success { + baseLogData = append(baseLogData, "object", result) + } + logger.V(1).Info("outgoing authorization response", baseLogData...) // debug + } +} + func buildResponseHeaders(headers []map[string]string) []*envoy_core.HeaderValueOption { responseHeaders := make([]*envoy_core.HeaderValueOption, 0) diff --git a/pkg/service/auth_pipeline.go b/pkg/service/auth_pipeline.go index 75ed9318..d007e4f1 100644 --- a/pkg/service/auth_pipeline.go +++ b/pkg/service/auth_pipeline.go @@ -6,17 +6,13 @@ import ( "sync" "github.com/kuadrant/authorino/pkg/common" + "github.com/kuadrant/authorino/pkg/common/log" "github.com/kuadrant/authorino/pkg/config" envoy_auth "github.com/envoyproxy/go-control-plane/envoy/service/auth/v3" envoy_type "github.com/envoyproxy/go-control-plane/envoy/type/v3" "github.com/gogo/googleapis/google/rpc" "golang.org/x/net/context" - ctrl "sigs.k8s.io/controller-runtime" -) - -var ( - authCtxLog = ctrl.Log.WithName("Authorino").WithName("AuthPipeline") ) type EvaluationResponse struct { @@ -41,44 +37,47 @@ func newEvaluationResponse(evaluator common.AuthConfigEvaluator, obj interface{} } } +// NewAuthPipeline creates an AuthPipeline instance +func NewAuthPipeline(parentCtx context.Context, req *envoy_auth.CheckRequest, apiConfig config.APIConfig) common.AuthPipeline { + logger := log.FromContext(parentCtx).WithName("authpipeline") + + return &AuthPipeline{ + Context: log.IntoContext(parentCtx, logger), + Request: req, + API: &apiConfig, + Identity: make(map[*config.IdentityConfig]interface{}), + Metadata: make(map[*config.MetadataConfig]interface{}), + Authorization: make(map[*config.AuthorizationConfig]interface{}), + Response: make(map[*config.ResponseConfig]interface{}), + Logger: logger, + } +} + // AuthPipeline evaluates the context of an auth request upon the authconfigs defined for the requested API // Throughout the pipeline, user identity, ad hoc metadata and authorization policies are evaluated and their // corresponding resulting objects stored in the respective maps. type AuthPipeline struct { - ParentContext *context.Context - Request *envoy_auth.CheckRequest - API *config.APIConfig + Context context.Context + Request *envoy_auth.CheckRequest + API *config.APIConfig Identity map[*config.IdentityConfig]interface{} Metadata map[*config.MetadataConfig]interface{} Authorization map[*config.AuthorizationConfig]interface{} Response map[*config.ResponseConfig]interface{} -} -// NewAuthPipeline creates an AuthPipeline instance -func NewAuthPipeline(parentCtx context.Context, req *envoy_auth.CheckRequest, apiConfig config.APIConfig) AuthPipeline { - return AuthPipeline{ - ParentContext: &parentCtx, - Request: req, - API: &apiConfig, - Identity: make(map[*config.IdentityConfig]interface{}), - Metadata: make(map[*config.MetadataConfig]interface{}), - Authorization: make(map[*config.AuthorizationConfig]interface{}), - Response: make(map[*config.ResponseConfig]interface{}), - } + Logger log.Logger } func (pipeline *AuthPipeline) evaluateAuthConfig(config common.AuthConfigEvaluator, ctx context.Context, respChannel *chan EvaluationResponse, successCallback func(), failureCallback func()) { if err := common.CheckContext(ctx); err != nil { - authCtxLog.Info("Skipping auth config", "config", config, "reason", err) + pipeline.Logger.V(1).Info("skipping config", "config", config, "reason", err) return } if authObj, err := config.Call(pipeline, ctx); err != nil { *respChannel <- newEvaluationResponse(config, nil, err) - authCtxLog.Info("Failed to evaluate auth object", "config", config, "error", err) - if failureCallback != nil { failureCallback() } @@ -94,7 +93,7 @@ func (pipeline *AuthPipeline) evaluateAuthConfig(config common.AuthConfigEvaluat type authConfigEvaluationStrategy func(conf common.AuthConfigEvaluator, ctx context.Context, respChannel *chan EvaluationResponse, cancel func()) func (pipeline *AuthPipeline) evaluateAuthConfigs(authConfigs []common.AuthConfigEvaluator, respChannel *chan EvaluationResponse, evaluate authConfigEvaluationStrategy) { - ctx, cancel := context.WithCancel(*pipeline.ParentContext) + ctx, cancel := context.WithCancel(pipeline.Context) waitGroup := new(sync.WaitGroup) waitGroup.Add(len(authConfigs)) @@ -128,6 +127,7 @@ func (pipeline *AuthPipeline) evaluateAnyAuthConfig(authConfigs []common.AuthCon } func (pipeline *AuthPipeline) evaluateIdentityConfigs() EvaluationResponse { + logger := pipeline.Logger.WithName("identity").V(1) configs := pipeline.API.IdentityConfigs count := len(configs) respChannel := make(chan EvaluationResponse, count) @@ -151,7 +151,7 @@ func (pipeline *AuthPipeline) evaluateIdentityConfigs() EvaluationResponse { if extendedObj, err := conf.ResolveExtendedProperties(pipeline); err != nil { resp.Error = err - authCtxLog.Info("Identity", "config", conf, "error", err) + logger.Error(err, "failed to extend identity object", "config", conf, "object", obj) if count == 1 { return resp } else { @@ -160,12 +160,12 @@ func (pipeline *AuthPipeline) evaluateIdentityConfigs() EvaluationResponse { } else { pipeline.Identity[conf] = extendedObj - authCtxLog.Info("Identity", "config", conf, "authObj", extendedObj) + logger.Info("identity validated", "config", conf, "object", extendedObj) return resp } } else { err := resp.Error - authCtxLog.Info("Identity", "config", conf, "error", err) + logger.Info("cannot validate identity", "config", conf, "reason", err) if count == 1 { return resp } else { @@ -181,6 +181,7 @@ func (pipeline *AuthPipeline) evaluateIdentityConfigs() EvaluationResponse { } func (pipeline *AuthPipeline) evaluateMetadataConfigs() { + logger := pipeline.Logger.WithName("metadata").V(1) configs := pipeline.API.MetadataConfigs respChannel := make(chan EvaluationResponse, len(configs)) @@ -195,17 +196,22 @@ func (pipeline *AuthPipeline) evaluateMetadataConfigs() { if resp.Success() { pipeline.Metadata[conf] = obj - authCtxLog.Info("Metadata", "config", conf, "authObj", obj) + logger.Info("fetched auth metadata", "config", conf, "object", obj) } else { - authCtxLog.Info("Metadata", "config", conf, "error", resp.Error) + logger.Info("cannot fetch metadata", "config", conf, "reason", resp.Error) } } } func (pipeline *AuthPipeline) evaluateAuthorizationConfigs() EvaluationResponse { + logger := pipeline.Logger.WithName("authorization").V(1) configs := pipeline.API.AuthorizationConfigs respChannel := make(chan EvaluationResponse, len(configs)) + if logger.Enabled() { + logger.Info("evaluating for input", "input", pipeline.GetDataForAuthorization()) + } + go func() { defer close(respChannel) pipeline.evaluateAllAuthConfigs(configs, &respChannel) @@ -217,9 +223,9 @@ func (pipeline *AuthPipeline) evaluateAuthorizationConfigs() EvaluationResponse if resp.Success() { pipeline.Authorization[conf] = obj - authCtxLog.Info("Authorization", "config", conf, "authObj", obj) + logger.Info("access granted", "config", conf, "object", obj) } else { - authCtxLog.Info("Authorization", "config", conf, "error", resp.Error) + logger.Info("access denied", "config", conf, "reason", resp.Error) return resp } } @@ -228,6 +234,7 @@ func (pipeline *AuthPipeline) evaluateAuthorizationConfigs() EvaluationResponse } func (pipeline *AuthPipeline) evaluateResponseConfigs() { + logger := pipeline.Logger.WithName("response").V(1) configs := pipeline.API.ResponseConfigs respChannel := make(chan EvaluationResponse, len(configs)) @@ -242,18 +249,18 @@ func (pipeline *AuthPipeline) evaluateResponseConfigs() { if resp.Success() { pipeline.Response[conf] = obj - authCtxLog.Info("Response", "config", conf, "authObj", obj) + logger.Info("dynamic response built", "config", conf, "object", obj) } else { - authCtxLog.Info("Response", "config", conf, "error", resp.Error) + logger.Info("cannot build dynamic response", "config", conf, "reason", resp.Error) } } } // Evaluate evaluates all steps of the auth pipeline (identity → metadata → policy enforcement) -func (pipeline *AuthPipeline) Evaluate() AuthResult { +func (pipeline *AuthPipeline) Evaluate() common.AuthResult { // phase 1: identity verification if resp := pipeline.evaluateIdentityConfigs(); !resp.Success() { - return pipeline.customizeDenyWith(AuthResult{ + return pipeline.customizeDenyWith(common.AuthResult{ Code: rpc.UNAUTHENTICATED, Message: resp.GetErrorMessage(), Headers: pipeline.API.GetChallengeHeaders(), @@ -265,7 +272,7 @@ func (pipeline *AuthPipeline) Evaluate() AuthResult { // phase 3: policy enforcement (authorization) if resp := pipeline.evaluateAuthorizationConfigs(); !resp.Success() { - return pipeline.customizeDenyWith(AuthResult{ + return pipeline.customizeDenyWith(common.AuthResult{ Code: rpc.PERMISSION_DENIED, Message: resp.GetErrorMessage(), }, pipeline.API.Unauthorized) @@ -276,17 +283,13 @@ func (pipeline *AuthPipeline) Evaluate() AuthResult { // auth result responseHeaders, responseMetadata := config.WrapResponses(pipeline.Response) - return AuthResult{ + return common.AuthResult{ Code: rpc.OK, Headers: []map[string]string{responseHeaders}, Metadata: responseMetadata, } } -func (pipeline *AuthPipeline) GetParentContext() *context.Context { - return pipeline.ParentContext -} - func (pipeline *AuthPipeline) GetRequest() *envoy_auth.CheckRequest { return pipeline.Request } @@ -358,7 +361,7 @@ func (pipeline *AuthPipeline) GetPostAuthorizationData() interface{} { return &authData } -func (pipeline *AuthPipeline) customizeDenyWith(authResult AuthResult, denyWith *config.DenyWithValues) AuthResult { +func (pipeline *AuthPipeline) customizeDenyWith(authResult common.AuthResult, denyWith *config.DenyWithValues) common.AuthResult { if denyWith != nil { if denyWith.Code != 0 { authResult.Status = envoy_type.StatusCode(denyWith.Code) diff --git a/pkg/service/auth_pipeline_test.go b/pkg/service/auth_pipeline_test.go index edd2750a..6ccc4c86 100644 --- a/pkg/service/auth_pipeline_test.go +++ b/pkg/service/auth_pipeline_test.go @@ -33,25 +33,32 @@ const rawRequest string = `{ } }` +var ( + requestMock = envoy_auth.CheckRequest{} + _ = json.Unmarshal([]byte(rawRequest), &requestMock) +) + type successConfig struct{} type failConfig struct{} -func (c *successConfig) Call(pipeline common.AuthPipeline, ctx context.Context) (interface{}, error) { +func (c *successConfig) Call(_ common.AuthPipeline, _ context.Context) (interface{}, error) { return nil, nil } -func (c *failConfig) Call(pipeline common.AuthPipeline, ctx context.Context) (interface{}, error) { +func (c *failConfig) Call(_ common.AuthPipeline, _ context.Context) (interface{}, error) { return nil, fmt.Errorf("Failed") } func newTestAuthPipeline(apiConfig config.APIConfig, req *envoy_auth.CheckRequest) AuthPipeline { - return NewAuthPipeline(context.TODO(), req, apiConfig) + p := NewAuthPipeline(context.TODO(), req, apiConfig) + pipeline, _ := p.(*AuthPipeline) + return *pipeline } func TestEvaluateOneAuthConfig(t *testing.T) { pipeline := newTestAuthPipeline(config.APIConfig{ IdentityConfigs: []common.AuthConfigEvaluator{&successConfig{}, &failConfig{}}, - }, nil) + }, &requestMock) respChannel := make(chan EvaluationResponse, 2) swap := false @@ -73,7 +80,7 @@ func TestEvaluateOneAuthConfig(t *testing.T) { func TestEvaluateOneAuthConfigWithoutSuccess(t *testing.T) { pipeline := newTestAuthPipeline(config.APIConfig{ IdentityConfigs: []common.AuthConfigEvaluator{&failConfig{}, &failConfig{}}, - }, nil) + }, &requestMock) respChannel := make(chan EvaluationResponse, 2) swap := false @@ -99,7 +106,7 @@ func TestEvaluateOneAuthConfigWithoutSuccess(t *testing.T) { func TestEvaluateOneAuthConfigWithoutError(t *testing.T) { pipeline := newTestAuthPipeline(config.APIConfig{ IdentityConfigs: []common.AuthConfigEvaluator{&successConfig{}, &successConfig{}}, - }, nil) + }, &requestMock) respChannel := make(chan EvaluationResponse, 2) swap := false @@ -125,7 +132,7 @@ func TestEvaluateOneAuthConfigWithoutError(t *testing.T) { func TestEvaluateAllAuthConfigs(t *testing.T) { pipeline := newTestAuthPipeline(config.APIConfig{ IdentityConfigs: []common.AuthConfigEvaluator{&successConfig{}, &successConfig{}}, - }, nil) + }, &requestMock) respChannel := make(chan EvaluationResponse, 2) swap := false @@ -151,7 +158,7 @@ func TestEvaluateAllAuthConfigs(t *testing.T) { func TestEvaluateAllAuthConfigsWithError(t *testing.T) { pipeline := newTestAuthPipeline(config.APIConfig{ IdentityConfigs: []common.AuthConfigEvaluator{&successConfig{}, &failConfig{}}, - }, nil) + }, &requestMock) respChannel := make(chan EvaluationResponse, 2) var err error @@ -173,7 +180,7 @@ func TestEvaluateAllAuthConfigsWithError(t *testing.T) { func TestEvaluateAllAuthConfigsWithoutSuccess(t *testing.T) { pipeline := newTestAuthPipeline(config.APIConfig{ IdentityConfigs: []common.AuthConfigEvaluator{&failConfig{}, &failConfig{}}, - }, nil) + }, &requestMock) respChannel := make(chan EvaluationResponse, 2) swap := false @@ -199,7 +206,7 @@ func TestEvaluateAllAuthConfigsWithoutSuccess(t *testing.T) { func TestEvaluateAnyAuthConfig(t *testing.T) { pipeline := newTestAuthPipeline(config.APIConfig{ IdentityConfigs: []common.AuthConfigEvaluator{&successConfig{}, &failConfig{}}, - }, nil) + }, &requestMock) respChannel := make(chan EvaluationResponse, 2) swap := false @@ -225,7 +232,7 @@ func TestEvaluateAnyAuthConfig(t *testing.T) { func TestEvaluateAnyAuthConfigsWithoutSuccess(t *testing.T) { pipeline := newTestAuthPipeline(config.APIConfig{ IdentityConfigs: []common.AuthConfigEvaluator{&failConfig{}, &failConfig{}}, - }, nil) + }, &requestMock) respChannel := make(chan EvaluationResponse, 2) swap := false @@ -251,7 +258,7 @@ func TestEvaluateAnyAuthConfigsWithoutSuccess(t *testing.T) { func TestEvaluateAnyAuthConfigsWithoutError(t *testing.T) { pipeline := newTestAuthPipeline(config.APIConfig{ IdentityConfigs: []common.AuthConfigEvaluator{&successConfig{}, &successConfig{}}, - }, nil) + }, &requestMock) respChannel := make(chan EvaluationResponse, 2) swap := false @@ -275,18 +282,15 @@ func TestEvaluateAnyAuthConfigsWithoutError(t *testing.T) { } func TestGetDataForAuthorization(t *testing.T) { - request := envoy_auth.CheckRequest{} - _ = json.Unmarshal([]byte(rawRequest), &request) - pipeline := newTestAuthPipeline(config.APIConfig{ IdentityConfigs: []common.AuthConfigEvaluator{&successConfig{}, &successConfig{}}, - }, &request) + }, &requestMock) data := pipeline.GetDataForAuthorization() if dataJSON, err := json.Marshal(&data); err != nil { t.Error(err) } else { - requestJSON, _ := json.Marshal(request.GetAttributes()) + requestJSON, _ := json.Marshal(requestMock.GetAttributes()) expectedJSON := fmt.Sprintf(`{"context":%s,"auth":{"identity":null,"metadata":{}}}`, requestJSON) assert.Equal(t, expectedJSON, string(dataJSON)) } diff --git a/pkg/service/auth_test.go b/pkg/service/auth_test.go index e9bc5370..da87737b 100644 --- a/pkg/service/auth_test.go +++ b/pkg/service/auth_test.go @@ -6,6 +6,7 @@ import ( "gotest.tools/assert" "github.com/kuadrant/authorino/pkg/cache" + "github.com/kuadrant/authorino/pkg/common" envoy_core "github.com/envoyproxy/go-control-plane/envoy/config/core/v3" envoy_auth "github.com/envoyproxy/go-control-plane/envoy/service/auth/v3" @@ -29,12 +30,11 @@ func TestSuccessResponse(t *testing.T) { } var resp *envoy_auth.OkHttpResponse - - resp = service.successResponse(AuthResult{}).GetOkResponse() + resp = service.successResponse(common.AuthResult{}, nil).GetOkResponse() assert.Equal(t, len(resp.GetHeaders()), 0) headers := []map[string]string{{"X-Custom-Header": "some-value"}} - resp = service.successResponse(AuthResult{Headers: headers}).GetOkResponse() + resp = service.successResponse(common.AuthResult{Headers: headers}, nil).GetOkResponse() assert.Equal(t, getHeader(resp.GetHeaders(), "X-Custom-Header"), "some-value") } @@ -46,26 +46,26 @@ func TestDeniedResponse(t *testing.T) { var resp *envoy_auth.DeniedHttpResponse var extraHeaders []map[string]string - resp = service.deniedResponse(AuthResult{Code: rpc.FAILED_PRECONDITION, Message: "Invalid request"}).GetDeniedResponse() + resp = service.deniedResponse(common.AuthResult{Code: rpc.FAILED_PRECONDITION, Message: "Invalid request"}).GetDeniedResponse() assert.Equal(t, resp.Status.Code, envoy_type.StatusCode_BadRequest) assert.Equal(t, getHeader(resp.GetHeaders(), X_EXT_AUTH_REASON_HEADER), "Invalid request") - resp = service.deniedResponse(AuthResult{Code: rpc.NOT_FOUND, Message: "Service not found"}).GetDeniedResponse() + resp = service.deniedResponse(common.AuthResult{Code: rpc.NOT_FOUND, Message: "Service not found"}).GetDeniedResponse() assert.Equal(t, resp.Status.Code, envoy_type.StatusCode_NotFound) assert.Equal(t, getHeader(resp.GetHeaders(), X_EXT_AUTH_REASON_HEADER), "Service not found") extraHeaders = []map[string]string{{"WWW-Authenticate": "Bearer"}} - resp = service.deniedResponse(AuthResult{Code: rpc.UNAUTHENTICATED, Message: "Unauthenticated", Headers: extraHeaders}).GetDeniedResponse() + resp = service.deniedResponse(common.AuthResult{Code: rpc.UNAUTHENTICATED, Message: "Unauthenticated", Headers: extraHeaders}).GetDeniedResponse() assert.Equal(t, resp.Status.Code, envoy_type.StatusCode_Unauthorized) assert.Equal(t, getHeader(resp.GetHeaders(), X_EXT_AUTH_REASON_HEADER), "Unauthenticated") assert.Equal(t, getHeader(resp.GetHeaders(), "WWW-Authenticate"), "Bearer") - resp = service.deniedResponse(AuthResult{Code: rpc.PERMISSION_DENIED, Message: "Unauthorized"}).GetDeniedResponse() + resp = service.deniedResponse(common.AuthResult{Code: rpc.PERMISSION_DENIED, Message: "Unauthorized"}).GetDeniedResponse() assert.Equal(t, resp.Status.Code, envoy_type.StatusCode_Forbidden) assert.Equal(t, getHeader(resp.GetHeaders(), X_EXT_AUTH_REASON_HEADER), "Unauthorized") extraHeaders = []map[string]string{{"Location": "http://my-app.io/login"}} - resp = service.deniedResponse(AuthResult{Code: rpc.UNAUTHENTICATED, Status: envoy_type.StatusCode_Found, Message: "Please login", Headers: extraHeaders}).GetDeniedResponse() + resp = service.deniedResponse(common.AuthResult{Code: rpc.UNAUTHENTICATED, Status: envoy_type.StatusCode_Found, Message: "Please login", Headers: extraHeaders}).GetDeniedResponse() assert.Equal(t, resp.Status.Code, envoy_type.StatusCode_Found) assert.Equal(t, getHeader(resp.GetHeaders(), X_EXT_AUTH_REASON_HEADER), "Please login") assert.Equal(t, getHeader(resp.GetHeaders(), "Location"), "http://my-app.io/login") diff --git a/pkg/service/oidc.go b/pkg/service/oidc.go index 41873dfa..42271d68 100644 --- a/pkg/service/oidc.go +++ b/pkg/service/oidc.go @@ -1,62 +1,72 @@ package service import ( + "crypto/md5" + "encoding/hex" "fmt" "net/http" "strings" "github.com/kuadrant/authorino/pkg/cache" "github.com/kuadrant/authorino/pkg/common" - - ctrl "sigs.k8s.io/controller-runtime" + "github.com/kuadrant/authorino/pkg/common/log" ) -var oidcServiceLog = ctrl.Log.WithName("authorino").WithName("OidcService") - // OidcService implements an HTTP server for OpenID Connect Discovery type OidcService struct { Cache cache.Cache } func (o *OidcService) ServeHTTP(writer http.ResponseWriter, req *http.Request) { - urlParts := strings.Split(req.URL.String(), "/") - - realm := strings.Join(urlParts[1:3], "/") - config := urlParts[3] - path := strings.Join(urlParts[4:], "/") - if strings.HasSuffix(path, "/") { - path = path[:len(path)-1] - } - path = "/" + path + uri := req.URL.String() - oidcServiceLog.Info("request received", "realm", realm, "config", config, "path", path) + requestId := md5.Sum([]byte(fmt.Sprint(req))) + requestLogger := log.WithName("service").WithName("oidc").WithValues("request id", hex.EncodeToString(requestId[:16]), "uri", uri) var statusCode int var responseBody string - if wristband := o.findWristbandIssuer(realm, config); wristband != nil { - var err error + uriParts := strings.Split(uri, "/") - switch path { - case "/.well-known/openid-configuration": - responseBody, err = wristband.OpenIDConfig() - case "/.well-known/openid-connect/certs": - responseBody, err = wristband.JWKS() - default: - statusCode = http.StatusNotFound - err = fmt.Errorf("Not found") + if len(uriParts) >= 4 { + realm := strings.Join(uriParts[1:3], "/") + config := uriParts[3] + path := strings.Join(uriParts[4:], "/") + if strings.HasSuffix(path, "/") { + path = path[:len(path)-1] } + path = "/" + path - if err == nil { - statusCode = http.StatusOK - writer.Header().Add("Content-Type", "application/json") - } else { - if statusCode == 0 { - statusCode = http.StatusInternalServerError + requestLogger.Info("request received", "realm", realm, "config", config, "path", path) + + if wristband := o.findWristbandIssuer(realm, config); wristband != nil { + var err error + + switch path { + case "/.well-known/openid-configuration": + responseBody, err = wristband.OpenIDConfig() + case "/.well-known/openid-connect/certs": + responseBody, err = wristband.JWKS() + default: + statusCode = http.StatusNotFound + err = fmt.Errorf("Not found") + } + + if err == nil { + statusCode = http.StatusOK + writer.Header().Add("Content-Type", "application/json") + } else { + if statusCode == 0 { + statusCode = http.StatusInternalServerError + } + responseBody = err.Error() } - responseBody = err.Error() + } else { + statusCode = http.StatusNotFound + responseBody = "Not found" } } else { + requestLogger.Info("request received") statusCode = http.StatusNotFound responseBody = "Not found" } @@ -64,7 +74,9 @@ func (o *OidcService) ServeHTTP(writer http.ResponseWriter, req *http.Request) { writer.WriteHeader(statusCode) if _, err := writer.Write([]byte(responseBody)); err != nil { - oidcServiceLog.Error(err, "failed to serve oidc request") + requestLogger.Error(err, "failed to serve oidc request") + } else { + requestLogger.Info("response sent", "status", statusCode) } }