flows: optimise logging
This commit is contained in:
Jens Langhammer
parent
624206281e
commit
09bdcfaab0
|
|
@ -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
|
||||
|
|
|
|||
|
|
@ -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"
|
||||
|
|
|
|||
Reference in a new issue