From 624206281e3cf55934c0ea4748748a1a80c00e65 Mon Sep 17 00:00:00 2001 From: Jens Langhammer Date: Tue, 2 Feb 2021 15:50:42 +0100 Subject: [PATCH] policies: optimise logging --- authentik/core/admin.py | 4 ---- authentik/lib/logging.py | 13 ------------- authentik/lib/sentry.py | 1 - authentik/policies/engine.py | 11 ++++++----- authentik/policies/process.py | 14 ++++++-------- authentik/root/settings.py | 3 +-- authentik/root/urls.py | 2 +- 7 files changed, 14 insertions(+), 34 deletions(-) diff --git a/authentik/core/admin.py b/authentik/core/admin.py index cb37367ce..e6ba03829 100644 --- a/authentik/core/admin.py +++ b/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) diff --git a/authentik/lib/logging.py b/authentik/lib/logging.py index 7ec26f48c..899391f26 100644 --- a/authentik/lib/logging.py +++ b/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 diff --git a/authentik/lib/sentry.py b/authentik/lib/sentry.py index 58044b918..d78cc2df4 100644 --- a/authentik/lib/sentry.py +++ b/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 diff --git a/authentik/policies/engine.py b/authentik/policies/engine.py index 8a13ae29a..e29f6ae81 100644 --- a/authentik/policies/engine.py +++ b/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: diff --git a/authentik/policies/process.py b/authentik/policies/process.py index da6a58be3..900614558 100644 --- a/authentik/policies/process.py +++ b/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 diff --git a/authentik/root/settings.py b/authentik/root/settings.py index 99a005afc..87d704658 100644 --- a/authentik/root/settings.py +++ b/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), diff --git a/authentik/root/urls.py b/authentik/root/urls.py index e33bd535d..ec166b070 100644 --- a/authentik/root/urls.py +++ b/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, )