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

@@ -9,3 +9,4 @@ examples
 tmp
 
 .idea
+.vscode

.gitignore

@@ -18,6 +18,7 @@ vendor
 
 # editor and IDE paraphernalia
 .idea
+.vscode
 *.swp
 *.swo
 *~

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,23 +46,23 @@ import (
 // AuthConfigReconciler reconciles an AuthConfig object
 type AuthConfigReconciler struct {
 	client.Client
-	Log    logr.Logger
+	Logger logr.Logger
 	Scheme *runtime.Scheme
 	Cache  cache.Cache
 }
 
 // +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)
 	if err != nil && errors.IsNotFound(err) {
 
 		// 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
 			}

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

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

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,
 	})

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
 	}
 }

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,

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.