policies: optimise logging

authentik/core/admin.py

@@ -4,9 +4,6 @@ from django.apps import AppConfig, apps
 from django.contrib import admin
 from django.contrib.admin.sites import AlreadyRegistered
 from guardian.admin import GuardedModelAdmin
-from structlog.stdlib import get_logger
-
-LOGGER = get_logger()
 
 
 def admin_autoregister(app: AppConfig):
@@ -20,5 +17,4 @@ def admin_autoregister(app: AppConfig):
 
 for _app in apps.get_app_configs():
     if _app.label.startswith("authentik_"):
-        LOGGER.debug("Registering application for dj-admin", application=_app.label)
         admin_autoregister(_app)

authentik/lib/logging.py

@@ -1,7 +1,6 @@
 """logging helpers"""
 from logging import Logger
 from os import getpid
-from typing import Callable
 
 
 # pylint: disable=unused-argument
@@ -9,15 +8,3 @@ def add_process_id(logger: Logger, method_name: str, event_dict):
     """Add the current process ID"""
     event_dict["pid"] = getpid()
     return event_dict
-
-
-def add_common_fields(environment: str) -> Callable:
-    """Add a common field to easily search for authentik logs"""
-
-    def add_common_field(logger: Logger, method_name: str, event_dict):
-        """Add a common field to easily search for authentik logs"""
-        event_dict["app"] = "authentik"
-        event_dict["app_environment"] = environment
-        return event_dict
-
-    return add_common_field

authentik/lib/sentry.py

@@ -59,6 +59,5 @@ def before_send(event, hint):
     if "exc_info" in hint:
         _, exc_value, _ = hint["exc_info"]
         if isinstance(exc_value, ignored_classes):
-            LOGGER.info("Supressing error %r", exc_value)
             return None
     return event

authentik/policies/engine.py

@@ -8,14 +8,13 @@ from django.core.cache import cache
 from django.http import HttpRequest
 from sentry_sdk.hub import Hub
 from sentry_sdk.tracing import Span
-from structlog.stdlib import get_logger
+from structlog.stdlib import BoundLogger, get_logger
 
 from authentik.core.models import User
 from authentik.policies.models import Policy, PolicyBinding, PolicyBindingModel
 from authentik.policies.process import PolicyProcess, cache_key
 from authentik.policies.types import PolicyRequest, PolicyResult
 
-LOGGER = get_logger()
 CURRENT_PROCESS = current_process()
 
 
@@ -49,6 +48,7 @@ class PolicyEngine:
     use_cache: bool
     request: PolicyRequest
 
+    logger: BoundLogger
     mode: PolicyEngineMode
     # Allow objects with no policies attached to pass
     empty_result: bool
@@ -62,6 +62,7 @@ class PolicyEngine:
     def __init__(
         self, pbm: PolicyBindingModel, user: User, request: HttpRequest = None
     ):
+        self.logger = get_logger().bind()
         self.mode = PolicyEngineMode.MODE_AND
         # For backwards compatibility, set empty_result to true
         # objects with no policies attached will pass.
@@ -105,18 +106,18 @@ class PolicyEngine:
                 key = cache_key(binding, self.request)
                 cached_policy = cache.get(key, None)
                 if cached_policy and self.use_cache:
-                    LOGGER.debug(
+                    self.logger.debug(
                         "P_ENG: Taking result from cache",
                         policy=binding.policy,
                         cache_key=key,
                     )
                     self.__cached_policies.append(cached_policy)
                     continue
-                LOGGER.debug("P_ENG: Evaluating policy", policy=binding.policy)
+                self.logger.debug("P_ENG: Evaluating policy", policy=binding.policy)
                 our_end, task_end = Pipe(False)
                 task = PolicyProcess(binding, self.request, task_end)
                 task.daemon = False
-                LOGGER.debug("P_ENG: Starting Process", policy=binding.policy)
+                self.logger.debug("P_ENG: Starting Process", policy=binding.policy)
                 if not CURRENT_PROCESS._config.get("daemon"):
                     task.run()
                 else:

authentik/policies/process.py

@@ -17,6 +17,9 @@ from authentik.policies.types import PolicyRequest, PolicyResult
 LOGGER = get_logger()
 TRACEBACK_HEADER = "Traceback (most recent call last):\n"
 
+FORK_CTX = get_context("fork")
+PROCESS_CLASS = FORK_CTX.Process
+
 
 def cache_key(binding: PolicyBinding, request: PolicyRequest) -> str:
     """Generate Cache key for policy"""
@@ -28,10 +31,6 @@ def cache_key(binding: PolicyBinding, request: PolicyRequest) -> str:
     return prefix
 
 
-FORK_CTX = get_context("fork")
-PROCESS_CLASS = FORK_CTX.Process
-
-
 class PolicyProcess(PROCESS_CLASS):
     """Evaluate a single policy within a seprate process"""
 
@@ -103,17 +102,16 @@ class PolicyProcess(PROCESS_CLASS):
         # Invert result if policy.negate is set
         if self.binding.negate:
             policy_result.passing = not policy_result.passing
+        key = cache_key(self.binding, self.request)
+        cache.set(key, policy_result)
         LOGGER.debug(
-            "P_ENG(proc): Finished",
+            "P_ENG(proc): finished and cached ",
             policy=self.binding.policy,
             result=policy_result,
             process="PolicyProcess",
             passing=policy_result.passing,
             user=self.request.user,
         )
-        key = cache_key(self.binding, self.request)
-        cache.set(key, policy_result)
-        LOGGER.debug("P_ENG(proc): Cached policy evaluation", key=key)
         return policy_result
 
     def run(self):  # pragma: no cover

authentik/root/settings.py

@@ -27,7 +27,7 @@ from sentry_sdk.integrations.redis import RedisIntegration
 from authentik import __version__
 from authentik.core.middleware import structlog_add_request_id
 from authentik.lib.config import CONFIG
-from authentik.lib.logging import add_common_fields, add_process_id
+from authentik.lib.logging import add_process_id
 from authentik.lib.sentry import before_send
 
 
@@ -363,7 +363,6 @@ structlog.configure_once(
         structlog.stdlib.add_logger_name,
         structlog.threadlocal.merge_threadlocal_context,
         add_process_id,
-        add_common_fields(CONFIG.y("error_reporting.environment", "customer")),
         structlog_add_request_id,
         structlog.stdlib.PositionalArgumentsFormatter(),
         structlog.processors.TimeStamper(fmt="iso", utc=False),

authentik/root/urls.py

@@ -50,7 +50,7 @@ for _authentik_app in get_apps():
         LOGGER.debug(
             "Mounted URLs",
             app_name=_authentik_app.name,
-            mountpoint=mountpoint,
+            app_mountpoint=mountpoint,
             namespace=namespace,
         )