From 09bdcfaab01c088f163b153b6dd635e9a390c2ba Mon Sep 17 00:00:00 2001 From: Jens Langhammer Date: Tue, 2 Feb 2021 16:17:59 +0100 Subject: [PATCH] flows: optimise logging --- authentik/flows/planner.py | 51 +++++++++++++++++++++----------------- authentik/flows/views.py | 49 +++++++++++++++++------------------- 2 files changed, 51 insertions(+), 49 deletions(-) diff --git a/authentik/flows/planner.py b/authentik/flows/planner.py index 2c82f5dc8..2f4f390f9 100644 --- a/authentik/flows/planner.py +++ b/authentik/flows/planner.py @@ -6,7 +6,7 @@ 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.events.models import cleanse_dict @@ -15,8 +15,6 @@ from authentik.flows.markers import ReevaluateMarker, StageMarker from authentik.flows.models import Flow, FlowStageBinding, Stage from authentik.policies.engine import PolicyEngine -LOGGER = get_logger() - PLAN_CONTEXT_PENDING_USER = "pending_user" PLAN_CONTEXT_SSO = "is_sso" PLAN_CONTEXT_REDIRECT = "redirect" @@ -43,6 +41,8 @@ class FlowPlan: context: Dict[str, Any] = field(default_factory=dict) markers: List[StageMarker] = field(default_factory=list) + _logger: BoundLogger = field(default_factory=get_logger) + def append(self, stage: Stage, marker: Optional[StageMarker] = None): """Append `stage` to all stages, optionall with stage marker""" self.stages.append(stage) @@ -56,10 +56,14 @@ class FlowPlan: marker = self.markers[0] if marker.__class__ is not StageMarker: - LOGGER.debug("f(plan_inst): stage has marker", stage=stage, marker=marker) + self._logger.debug( + "f(plan_inst): stage has marker", stage=stage, marker=marker + ) marked_stage = marker.process(self, stage, http_request) if not marked_stage: - LOGGER.debug("f(plan_inst): marker returned none, next stage", stage=stage) + self._logger.debug( + "f(plan_inst): marker returned none, next stage", stage=stage + ) self.stages.remove(stage) self.markers.remove(marker) if not self.has_stages: @@ -88,10 +92,13 @@ class FlowPlanner: flow: Flow + _logger: BoundLogger + def __init__(self, flow: Flow): self.use_cache = True self.allow_empty_flows = False self.flow = flow + self._logger = get_logger().bind(flow=flow) def plan( self, request: HttpRequest, default_context: Optional[Dict[str, Any]] = None @@ -103,7 +110,9 @@ class FlowPlanner: span.set_data("flow", self.flow) span.set_data("request", request) - LOGGER.debug("f(plan): Starting planning process", flow=self.flow) + self._logger.debug( + "f(plan): starting planning process", + ) # Bit of a workaround here, if there is a pending user set in the default context # we use that user for our cache key # to make sure they don't get the generic response @@ -125,15 +134,16 @@ class FlowPlanner: cached_plan_key = cache_key(self.flow, user) cached_plan = cache.get(cached_plan_key, None) if cached_plan and self.use_cache: - LOGGER.debug( - "f(plan): Taking plan from cache", - flow=self.flow, + self._logger.debug( + "f(plan): taking plan from cache", key=cached_plan_key, ) # Reset the context as this isn't factored into caching cached_plan.context = default_context or {} return cached_plan - LOGGER.debug("f(plan): building plan", flow=self.flow) + self._logger.debug( + "f(plan): building plan", + ) plan = self._build_plan(user, request, default_context) cache.set(cache_key(self.flow, user), plan) if not plan.stages and not self.allow_empty_flows: @@ -165,39 +175,34 @@ class FlowPlanner: stage = binding.stage marker = StageMarker() if binding.evaluate_on_plan: - LOGGER.debug( + self._logger.debug( "f(plan): evaluating on plan", stage=binding.stage, - flow=self.flow, ) engine = PolicyEngine(binding, user, request) engine.request.context = plan.context engine.build() if engine.passing: - LOGGER.debug( - "f(plan): Stage passing", + self._logger.debug( + "f(plan): stage passing", stage=binding.stage, - flow=self.flow, ) else: stage = None else: - LOGGER.debug( + self._logger.debug( "f(plan): not evaluating on plan", stage=binding.stage, - flow=self.flow, ) if binding.re_evaluate_policies and stage: - LOGGER.debug( - "f(plan): Stage has re-evaluate marker", + self._logger.debug( + "f(plan): stage has re-evaluate marker", stage=binding.stage, - flow=self.flow, ) marker = ReevaluateMarker(binding=binding, user=user) if stage: plan.append(stage, marker) - LOGGER.debug( - "f(plan): Finished building", - flow=self.flow, + self._logger.debug( + "f(plan): finished building", ) return plan diff --git a/authentik/flows/views.py b/authentik/flows/views.py index 18afc36b2..d8bfa0453 100644 --- a/authentik/flows/views.py +++ b/authentik/flows/views.py @@ -15,7 +15,7 @@ from django.template.response import TemplateResponse from django.utils.decorators import method_decorator from django.views.decorators.clickjacking import xframe_options_sameorigin from django.views.generic import TemplateView, View -from structlog.stdlib import get_logger +from structlog.stdlib import BoundLogger, get_logger from authentik.core.models import USER_ATTRIBUTE_DEBUG from authentik.events.models import cleanse_dict @@ -49,15 +49,18 @@ class FlowExecutorView(View): current_stage: Stage current_stage_view: View + _logger: BoundLogger + def setup(self, request: HttpRequest, flow_slug: str): - super().setup(request, flow_slug=flow_slug) + super().setup(request) self.flow = get_object_or_404(Flow.objects.select_related(), slug=flow_slug) + self._logger = get_logger().bind(flow_slug=flow_slug) def handle_invalid_flow(self, exc: BaseException) -> HttpResponse: """When a flow is non-applicable check if user is on the correct domain""" if NEXT_ARG_NAME in self.request.GET: if not is_url_absolute(self.request.GET.get(NEXT_ARG_NAME)): - LOGGER.debug("f(exec): Redirecting to next on fail") + self._logger.debug("f(exec): Redirecting to next on fail") return redirect(self.request.GET.get(NEXT_ARG_NAME)) message = exc.__doc__ if exc.__doc__ else str(exc) return self.stage_invalid(error_message=message) @@ -67,27 +70,26 @@ class FlowExecutorView(View): if SESSION_KEY_PLAN in self.request.session: self.plan = self.request.session[SESSION_KEY_PLAN] if self.plan.flow_pk != self.flow.pk.hex: - LOGGER.warning( + self._logger.warning( "f(exec): Found existing plan for other flow, deleteing plan", - flow_slug=flow_slug, ) # Existing plan is deleted from session and instance self.plan = None self.cancel() - LOGGER.debug("f(exec): Continuing existing plan", flow_slug=flow_slug) + self._logger.debug("f(exec): Continuing existing plan") # Don't check session again as we've either already loaded the plan or we need to plan if not self.plan: - LOGGER.debug( - "f(exec): No active Plan found, initiating planner", flow_slug=flow_slug - ) + self._logger.debug("f(exec): No active Plan found, initiating planner") try: self.plan = self._initiate_plan() except FlowNonApplicableException as exc: - LOGGER.warning("f(exec): Flow not applicable to current user", exc=exc) + self._logger.warning( + "f(exec): Flow not applicable to current user", exc=exc + ) return to_stage_response(self.request, self.handle_invalid_flow(exc)) except EmptyFlowException as exc: - LOGGER.warning("f(exec): Flow is empty", exc=exc) + self._logger.warning("f(exec): Flow is empty", exc=exc) # To match behaviour with loading an empty flow plan from cache, # we don't show an error message here, but rather call _flow_done() return self._flow_done() @@ -95,10 +97,10 @@ class FlowExecutorView(View): # as it hasn't been successfully passed yet next_stage = self.plan.next(self.request) if not next_stage: - LOGGER.debug("f(exec): no more stages, flow is done.") + self._logger.debug("f(exec): no more stages, flow is done.") return self._flow_done() self.current_stage = next_stage - LOGGER.debug( + self._logger.debug( "f(exec): Current stage", current_stage=self.current_stage, flow_slug=self.flow.slug, @@ -112,32 +114,30 @@ class FlowExecutorView(View): def get(self, request: HttpRequest, *args, **kwargs) -> HttpResponse: """pass get request to current stage""" - LOGGER.debug( + self._logger.debug( "f(exec): Passing GET", view_class=class_to_path(self.current_stage_view.__class__), stage=self.current_stage, - flow_slug=self.flow.slug, ) try: stage_response = self.current_stage_view.get(request, *args, **kwargs) return to_stage_response(request, stage_response) except Exception as exc: # pylint: disable=broad-except - LOGGER.exception(exc) + self._logger.exception(exc) return to_stage_response(request, FlowErrorResponse(request, exc)) def post(self, request: HttpRequest, *args, **kwargs) -> HttpResponse: """pass post request to current stage""" - LOGGER.debug( + self._logger.debug( "f(exec): Passing POST", view_class=class_to_path(self.current_stage_view.__class__), stage=self.current_stage, - flow_slug=self.flow.slug, ) try: stage_response = self.current_stage_view.post(request, *args, **kwargs) return to_stage_response(request, stage_response) except Exception as exc: # pylint: disable=broad-except - LOGGER.exception(exc) + self._logger.exception(exc) return to_stage_response(request, FlowErrorResponse(request, exc)) def _initiate_plan(self) -> FlowPlan: @@ -163,26 +163,23 @@ class FlowExecutorView(View): def stage_ok(self) -> HttpResponse: """Callback called by stages upon successful completion. Persists updated plan and context to session.""" - LOGGER.debug( + self._logger.debug( "f(exec): Stage ok", stage_class=class_to_path(self.current_stage_view.__class__), - flow_slug=self.flow.slug, ) self.plan.pop() self.request.session[SESSION_KEY_PLAN] = self.plan if self.plan.stages: - LOGGER.debug( + self._logger.debug( "f(exec): Continuing with next stage", reamining=len(self.plan.stages), - flow_slug=self.flow.slug, ) return redirect_with_qs( "authentik_flows:flow-executor", self.request.GET, **self.kwargs ) # User passed all stages - LOGGER.debug( + self._logger.debug( "f(exec): User passed all stages", - flow_slug=self.flow.slug, context=cleanse_dict(self.plan.context), ) return self._flow_done() @@ -193,7 +190,7 @@ class FlowExecutorView(View): Optionally, an exception can be passed, which will be shown if the current user is a superuser.""" - LOGGER.debug("f(exec): Stage invalid", flow_slug=self.flow.slug) + self._logger.debug("f(exec): Stage invalid") self.cancel() response = AccessDeniedResponse( self.request, template="flows/denied_shell.html"